From 00111570b4066f4709abd01505ed51b869b89d1b Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Sun, 27 Sep 2026 22:20:58 -0400 Subject: [PATCH 01/13] Renew the publisher lease on the schedule of the claim that stamped its row The lease thread renews a third of the TTL after the last renewal, and the service counted an index pass as one: index_bounded() stamped last_renew_ns_ whenever indexer_.index() returned having indexed OR skipped a pack. A pass over packs the catalog had already committed publishes nothing, so it renews nothing, yet it restarted the renewal clock. Packs that keep arriving already committed -- re-staged after a crash between an upload and its spool removal, or reconciled first at start -- held the renewal off for as long as they kept coming, and the row expired under a service still reporting the lease held. After a real publish the stamp also trailed the publish's own last renewal by its watermark INSERT, read-backs and inventory commit. The coordinator now records when the claim INSERT that stamped each lease's row was sent -- on the steady clock, taken before the INSERT goes out, so never after the server stamps the row -- CatalogWriter exposes it as lease_sent_ns(), and renew_lease_if_due() schedules from it. Only a claim that confirmed moves the schedule: the lease thread's own renewal, or the one a publish makes before its fenced statements. last_renew_ns_ is gone. Test first, in tests/test_native_capture_storage_live.py: with a 3 s TTL, a committed pack is re-staged into the spool every 0.1 s for 6 s, so every cycle uploads it again (the uploader finds and verifies it in the store) and indexes it as skipped. On main the snapshot said "held" over a dead lease row from 3.01 s on. Now the lease renews every 1 to 1.5 s, and the row never has less than a second left. --- native/csrc/catalog/catalog_writer.h | 7 ++ native/csrc/catalog/lease_coordinator.cpp | 14 +++- native/csrc/catalog/lease_coordinator.h | 4 ++ native/csrc/catalog/storage_service.cpp | 37 ++++------ native/csrc/catalog/storage_service.h | 1 - tests/test_native_capture_storage_live.py | 83 +++++++++++++++++++++++ 6 files changed, 119 insertions(+), 27 deletions(-) diff --git a/native/csrc/catalog/catalog_writer.h b/native/csrc/catalog/catalog_writer.h index 438c88dff..e292c7e62 100644 --- a/native/csrc/catalog/catalog_writer.h +++ b/native/csrc/catalog/catalog_writer.h @@ -89,6 +89,13 @@ class CatalogWriter { PublisherLease renew_lease(); void release_lease(); const PublisherLease* held_lease() const { return leases_->lease(); } + // steady_clock ns: when the claim INSERT that stamped the held lease's row + // was sent -- the lease thread's last renewal, or a publish's -- or 0 + // while none is held. + uint64_t lease_sent_ns() const { + const PublisherLease* held = leases_->lease(); + return held != nullptr ? held->sent_ns : 0; + } uint64_t allocate_version(); uint64_t max_version(const std::string& table, const std::string& column) const; diff --git a/native/csrc/catalog/lease_coordinator.cpp b/native/csrc/catalog/lease_coordinator.cpp index b54f49f56..d70cfa1c0 100644 --- a/native/csrc/catalog/lease_coordinator.cpp +++ b/native/csrc/catalog/lease_coordinator.cpp @@ -1,6 +1,7 @@ #include "lease_coordinator.h" #include +#include #include #include #include @@ -9,6 +10,13 @@ namespace dmi_catalog { namespace { +uint64_t steady_ns() { + return static_cast( + std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count()); +} + } // namespace std::string new_uuid_v4() { @@ -105,6 +113,9 @@ PublisherLease LeaseCoordinator::claim_with_rival( const LeaseHead current = head(); reject_live(current, lease_id); const uint64_t term = current.term + 1; + // Taken before the INSERT goes out, so never after the server stamps the + // row: the renewal schedule counts from here. + const uint64_t sent_ns = steady_ns(); insert(term, lease_id, holder); if (rival_lease_id.has_value()) { // The contested-claim scenario: a rival row lands between the @@ -132,7 +143,8 @@ PublisherLease LeaseCoordinator::claim_with_rival( lease_ = PublisherLease{ term, lease_id, holder, parse_u64_field(rows[0][1], "lease acquisition"), - parse_u64_field(rows[0][2], "lease expiry")}; + parse_u64_field(rows[0][2], "lease expiry"), + sent_ns}; return *lease_; } lease_.reset(); diff --git a/native/csrc/catalog/lease_coordinator.h b/native/csrc/catalog/lease_coordinator.h index 2c4df49c0..271b05f77 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -41,6 +41,10 @@ struct PublisherLease { std::string holder; uint64_t acquired_at_ns = 0; uint64_t expires_at_ns = 0; + // steady_clock ns: when the claim INSERT that stamped this row was sent. + // The server stamps the row no earlier, so it lives at least lease_ttl_ns + // past this on the claimant's own clock. + uint64_t sent_ns = 0; }; struct LeaseHead { diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index cc1254c96..2dabdde10 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -434,11 +434,12 @@ void CaptureStorageService::index_bounded(std::vector refs, work.pop_back(); IndexResultData result; try { + // Nothing here stamps a renewal: the schedule follows the lease itself + // (renew_lease_if_due), which only a claim that confirmed moves -- a + // pass that published nothing, over packs already committed, renewed + // nothing. std::lock_guard lease(lease_mutex_); result = indexer_.index(batch); - if (result.indexed_packs > 0 || result.skipped_packs > 0) { - last_renew_ns_ = steady_ns(); // a publish renews the lease - } } catch (const CatalogError& exc) { if (exc.kind() == CatalogError::Kind::kBatchTooLarge && batch.size() > 1) { const size_t middle = batch.size() / 2; @@ -632,28 +633,16 @@ void CaptureStorageService::keep_lease() { } void CaptureStorageService::renew_lease_if_due() { - // Renew once a third of the TTL has passed since last_renew_ns_. The lease - // thread wakes every ttl/6, so with no index() in the way the renewal - // fires within about a tick of falling due, leaving at least roughly half - // the TTL for it to land before the row expires. An index() can leave far - // less, or none. It holds lease_mutex_ throughout, so this thread cannot - // renew until it returns, and index_bounded() then stamps last_renew_ns_ - // whenever it indexed or skipped a pack, as though the row had just been - // renewed. After a publish that stamp trails the publish's own last - // renewal by the watermark INSERT, its read-backs and commit_packs; and - // it is taken even when every pack was already committed, so index() - // published nothing and renewed nothing. Whatever slack is left covers a - // renewal that runs late, not one that fails. A failed renewal costs the - // lease at once whatever the cause. A refusal drops it in the coordinator, - // and any ClickHouse error (transport, timeout, or a server error) takes - // renew_for_publish()'s catch, which quarantines the writer on the first - // error that survives the client's retries (a write is repeated only when - // its connection was never made; one that may have reached the server - // never is). + // Due a third of the TTL after the claim that stamped the lease row was + // sent -- this thread's last renewal, or the one a publish made before + // its fenced statements -- as the writer records it, so nothing but a + // confirmed claim moves the schedule. The lease thread looks every sixth + // of the TTL, so with the lease lock free a renewal starts within half the + // TTL of that send, and the row has the other half left. const uint64_t ttl = config_.writer.lease_ttl_ns; - if (ttl == 0 || steady_ns() - last_renew_ns_ < ttl / 3) return; + const uint64_t sent = writer_.lease_sent_ns(); + if (ttl == 0 || sent == 0 || steady_ns() - sent < ttl / 3) return; writer_.renew_lease(); - last_renew_ns_ = steady_ns(); held_elsewhere_since_ns_ = 0; std::lock_guard lock(state_mutex_); ++state_.lease_renewals; @@ -670,7 +659,6 @@ void CaptureStorageService::acquire_lease_at_start() { while (true) { try { writer_.acquire_lease(config_.holder); - last_renew_ns_ = steady_ns(); return; } catch (const CatalogError& exc) { if (!is_lease_refusal(exc) || config_.start_lease_wait_ns == 0) throw; @@ -724,7 +712,6 @@ bool CaptureStorageService::ensure_publisher_lease() { publish_lease_state(); return false; } - last_renew_ns_ = steady_ns(); held_elsewhere_since_ns_ = 0; next_claim_ns_ = 0; { diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index 3c798e04a..0b3d0fc49 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -229,7 +229,6 @@ class CaptureStorageService { // Serialises every use of writer_'s lease: the lease thread renews it // while cycles publish. Taken inside cycle_mutex_, never the other way. std::mutex lease_mutex_; - uint64_t last_renew_ns_ = 0; // guarded by lease_mutex_ // When a claim or renewal was first refused by another holder since the // lease was last held; 0 while none has been. Guarded by lease_mutex_. uint64_t held_elsewhere_since_ns_ = 0; diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 683d27150..61904e36f 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -953,6 +953,89 @@ def test_a_quarantined_service_leaves_new_packs_in_the_spool( assert sorted(captures) == sorted(tensors) +def _lease_row_live(client, prefix) -> bool: + """Whether the newest lease row on the catalog still keeps rivals out.""" + table = f"`{DATABASE}`.`{prefix}_publisher_lease`" + return client.execute( + f"SELECT max(expires_at_ns) > toUnixTimestamp64Nano(now64(9)) " + f"FROM {table} WHERE term = (SELECT max(term) FROM {table})")[0][0] == 1 + + +def _held_but_dead(log): + return [sample for sample in log if sample[1] == "held" and not sample[2]] + + +def _lease_row_left_s(client, prefix) -> float: + """Seconds the newest lease row has left on the server's clock; negative + once it has expired.""" + table = f"`{DATABASE}`.`{prefix}_publisher_lease`" + return client.execute( + f"SELECT (toInt64(max(expires_at_ns)) - " + f"toInt64(toUnixTimestamp64Nano(now64(9)))) / 1e9 " + f"FROM {table} WHERE term = (SELECT max(term) FROM {table})")[0][0] + + +def test_passes_over_committed_packs_do_not_hold_off_the_renewal( + fake_s3, tmp_path): + """The lease thread renews a third of the TTL after the last renewal, + and the service counted an index pass as one whenever it indexed or + SKIPPED a pack. A pass over packs the catalog had already committed + publishes nothing, so nothing renewed the row -- yet each such pass + restarted the renewal clock. Packs that keep arriving already committed + (re-staged after a crash between upload and spool removal, or reconciled + first at start) held the renewal off indefinitely, and the row expired + under a service still reporting the lease held. The schedule now runs + from when the claim that stamped the row was sent, whatever the passes + do.""" + import os + + spool_root = tmp_path / "spool" + _stage(spool_root, range(2)) + (ready,) = _ready(spool_root) + kept = tmp_path / ready.name + os.link(ready, kept) # the spool's copy goes once it is uploaded + with _catalog() as (client, catalog): + config = _storage_config( + fake_s3, catalog.table_prefix, reconcile_on_start=False, + lease_ttl_s=3.0, publish_timeout_s=1) + service = _service(config, spool_root) + service.start() + try: + service.flush(30.0) + before = service.snapshot() + assert before["indexed_packs"] == 1, before + + # Two TTLs of cycles that each upload the committed pack again + # (the uploader finds it in the store and verifies it) and index + # it: every pass skips it. + log, left = [], [] + origin = time.monotonic() + while time.monotonic() < origin + 6.0: + try: + os.link(kept, ready) + except FileExistsError: + pass + state = service.snapshot()["lease_state"] + log.append((round(time.monotonic() - origin, 2), state, + _lease_row_live(client, catalog.table_prefix))) + left.append(_lease_row_left_s(client, catalog.table_prefix)) + time.sleep(0.1) + after = service.snapshot() + service.rethrow_if_failed() + finally: + service.stop() + + assert after["indexed_packs"] == 1, after + assert after["uploaded_packs"] - before["uploaded_packs"] >= 10, after + assert not _held_but_dead(log), log + # A renewal falls due a third of the TTL after the last and the lease + # thread looks every sixth, so the row never has less than about half + # the TTL left; a third leaves room for a slow request. + assert min(left) > 1.0, left + # One every 1 to 1.5 s over the 6 s. + assert after["lease_renewals"] - before["lease_renewals"] >= 3, after + + def _latch_lines(err: str) -> list[str]: return [line for line in err.splitlines() if "indexing stopped" in line] From ac0adcbb6b8bae11de0cbe235d2ee446b2662d71 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Sun, 27 Sep 2026 22:31:27 -0400 Subject: [PATCH 02/13] Bound every request made under the publisher lease by its deadline A lease renewal is three ClickHouse requests -- the head read, the claim INSERT, the read-back -- and each was bounded only by the catalog client's request timeout, 60 s by default against a 15 s TTL, while the lease thread held the lease lock. Every other request made under that lock had the same bound: an index pass's version claim, descriptor INSERTs, publish and read-backs, a reconcile's replay-guard read. A catalog that accepted a request and never answered let the row expire with the service still reporting the lease held, and a rival could take the catalog before any error surfaced. The claim INSERT also carried no server-side cap, so the server could land it after the client had given up. A first attempt (never pushed) gave each lease statement a fixed (TTL / 3 - skew) / 4, 1.25 s at the defaults. Review found that it held only while the service was idle -- the index pass's own requests kept their 60 s under the lock -- and that it quarantined a slow but healthy catalog (a select_sequential_consistency read, a quorum INSERT whose wait it cut from 5 s to 1.25 s), failed start() outright on a cold server, and could go round silently: claim times out, quarantine, refused by its own late row, repeat, saying only "curl: Timeout was reached". This replaces it. The deadline. The server stamps a lease row no earlier than its claim INSERT was sent, and a rival whose clock runs clock_skew ahead sees it expire that much early, so on the claimant's steady clock the row keeps rivals out until lease deadline = claim INSERT sent + lease_ttl - clock_skew - 0.1 s the 0.1 s covering the time between a request failing and the writer saying so. Every request made under the lease has to be answered by then, however the time is spread across them, so one slow but healthy request may use all of it. - ClickHouseClient: a RequestDeadline is a thread-local, nestable scope holding an absolute steady-clock deadline, read afresh before every attempt, so a renewal inside the scope extends it at once. Each attempt's timeouts are cut to the whole milliseconds left; a request whose deadline has passed is not sent; #151's retries honour it -- no attempt, and no backoff sleep, past the deadline. ClickHouseError now says whether the request timed out and whether it can have reached the server (sent()), and a timeout names the bound that ended it and the knobs behind it. - LeaseCoordinator: its statements run under the held lease's deadline while that is still ahead. A claim made without a lease -- at start, or after a quarantine -- gets min(request timeout, TTL / 3) per request, and so does one made under a lease whose deadline has passed: the protocol's own reads still decide such a claim (a renewal that meets a successor is refused, a publish is fenced out), where refusing to send it would turn those known outcomes into unknown ones. The lease INSERTs carry the time left as max_execution_time and lock_acquire_timeout (whole seconds rounded down, a fraction under one; both accepted as URL settings by 25.12), with timeout_overflow_mode=throw, and insert_quorum_timeout becomes min(publish_timeout, time left). The statement text is unchanged, and tests/test_native_catalog_lease_live.py passes unmodified. - CaptureStorageService: every use of the lease goes through a LeaseScope, which takes the lease lock and installs the lease deadline for every request made under it; a lease whose deadline has passed is abandoned (quarantined, no tombstone) on the way in and out, so it is never used or reported held. The renewal schedule is unchanged (a third of the TTL after the claim that stamped the row was sent). - Slow catalogs. CatalogWriter::acquire_lease() quarantines only when the claim's INSERT can have reached the server: a claim whose head read timed out, or could not connect, wrote nothing, and is retried a lease tick later instead of a TTL. This deliberately differs from the Python oracle (acquire_publisher_lease), which quarantines on any error. start() retries a claim that timed out within start_lease_wait, waiting out a quarantine when it ends inside the wait. Lease claims and renewals that time out are counted until one succeeds (snapshot lease_timeouts); from the third, lease_timeout_error -- and last_error -- names lease_ttl_s, clock_skew_s, clickhouse_request_timeout_s and lease_ttl_s / 3 with their values. The service constructor and NativeCaptureStorageConfig require the renewal window -- TTL / 2, when a renewal starts at the latest, to the deadline -- to be at least 200 ms: clock_skew <= TTL / 2 - 0.3 s. Main checked only the fence margin (TTL - publish_timeout - skew >= 0.1 s), so this newly refuses a skew above TTL / 2 - 0.3 s that the fence admits -- above 7.2 s and up to 9.9 s at the defaults (TTL 15 s, publish 5 s) -- and newly accepts nothing. Against the first attempt's rule (skew <= TTL / 3 - 0.2 s) it accepts skews from there up to TTL / 2 - 0.3 s, 5 s at the defaults for one. The defaults and every configuration the suites use pass. docs/integration-api-v1.md states the bound and the rule. tests/tools/verify_replicated_quorum.py (its Keeper harness is gone, so not run) keeps expecting insert_quorum_timeout 5000 on the lease INSERTs: at its 30 s TTL the time left is 10 s or more. Not covered here: an index pass still reads its packs from the object store under the lease lock (the next commit). Tests first, each red on main and, where it guards against the first attempt, on that design rebuilt on #151's client: - tests/test_native_lease_request_bound.py (CPU; conformance_catalog against a scripted HTTP server): the lease INSERTs carry the time left as max_execution_time and lock_acquire_timeout (main: no cap; first attempt: TTL / 12, no lock_acquire_timeout); the quorum wait is capped by it (main: publish_timeout's 5000 ms against 4 s left); a stalled head read, INSERT or read-back of a claim fails within TTL / 3, naming the knobs (main: not bounded; first attempt: 250 ms, naming nothing); a stalled renewal fails 0.1 s before the row expires (first attempt: after 250 ms); retries stop at the deadline (main: all three 503 attempts, 1.5 s); only a claim that sent its INSERT quarantines (first attempt: the head-read case did too); a 2 s head read no longer fails the claim (first attempt: 1.25 s timeout); and the skew rule both ways for the native service, and for the Python config in tests/test_native_capture_storage_wiring.py. - tests/test_native_capture_storage_live.py, 3 s TTL and a 20 s request timeout through a TCP switch that can now stall only the requests a predicate picks, or hold one back: a stalled renewal (main: "held" over a dead row from 3.06 s); every catalog INSERT but the lease's stalled inside an index pass, the review's repro (main: "held" over a dead row from 2.99 s; first attempt: from 2.94 s) -- now quarantined before 3 s with the row still live; start() with its first lease read 1.5 s late (first attempt: start() failed with the 250 ms timeout) -- now held after one retry, well under the 3 s quarantine; a catalog that stops answering surfaces lease_timeout_error naming the knobs, cleared once the lease renews (both: no such field); and query_log shows the caps on the lease INSERTs. The switch now answers libcurl's Expect: 100-continue itself, so routing a statement over 1 KiB no longer adds a second. At this commit the CPU lease and wiring tests and the storage and lease live suites pass. --- docs/integration-api-v1.md | 6 + native/csrc/catalog/bindings_store.cpp | 2 + native/csrc/catalog/catalog_writer.cpp | 16 +- native/csrc/catalog/catalog_writer.h | 18 +- native/csrc/catalog/clickhouse_client.cpp | 125 ++++++- native/csrc/catalog/clickhouse_client.h | 69 +++- native/csrc/catalog/lease_coordinator.cpp | 160 ++++++-- native/csrc/catalog/lease_coordinator.h | 81 +++- native/csrc/catalog/storage_service.cpp | 168 ++++++++- native/csrc/catalog/storage_service.h | 52 ++- src/dmi/storage/native_capture.py | 42 ++- tests/test_native_capture_storage_live.py | 331 ++++++++++++++++- tests/test_native_capture_storage_wiring.py | 38 ++ tests/test_native_lease_request_bound.py | 389 ++++++++++++++++++++ tests/tools/verify_replicated_quorum.py | 10 +- 15 files changed, 1432 insertions(+), 75 deletions(-) create mode 100644 tests/test_native_lease_request_bound.py diff --git a/docs/integration-api-v1.md b/docs/integration-api-v1.md index 1d60f24ab..bcd7d1706 100644 --- a/docs/integration-api-v1.md +++ b/docs/integration-api-v1.md @@ -210,6 +210,12 @@ not use a `readonly=1` profile: the reader sends its query limits `publish_timeout_s` (10 s at the default 5 s publish timeout). A refused connection is retried for any statement; a reset, or a 5xx that is not a permanent ClickHouse error (such as a row limit or a denied grant), for reads only; and a timeout never. +While the storage service holds the publisher lease, every request it makes, +retries included, must also be answered by the lease deadline: `lease_ttl_s` +less `clock_skew_s` and 0.1 s after the claim that stamped the lease row was +sent. Each request of a claim made without a lease has +min(`clickhouse_request_timeout_s`, `lease_ttl_s` / 3). `clock_skew_s` must +therefore be at most `lease_ttl_s` / 2 - 0.3 s. The schedule's default factory creates a distinct `CaptureSchedule` for each config instance. `MonitoringEngine` stores the config, while concrete adaptors decide whether diff --git a/native/csrc/catalog/bindings_store.cpp b/native/csrc/catalog/bindings_store.cpp index 0d552487f..d07593772 100644 --- a/native/csrc/catalog/bindings_store.cpp +++ b/native/csrc/catalog/bindings_store.cpp @@ -134,6 +134,8 @@ py::dict snapshot_dict(const dc::StorageServiceSnapshot& s) { // CLOCK_MONOTONIC on Linux); 0.0 when not quarantined. out["quarantined_until"] = static_cast(s.quarantined_until_ns) / 1e9; out["lease_reacquisitions"] = s.lease_reacquisitions; + out["lease_timeouts"] = s.lease_timeouts; + out["lease_timeout_error"] = s.lease_timeout_error; out["last_error"] = s.last_error; return out; } diff --git a/native/csrc/catalog/catalog_writer.cpp b/native/csrc/catalog/catalog_writer.cpp index 1798352b7..b766d7148 100644 --- a/native/csrc/catalog/catalog_writer.cpp +++ b/native/csrc/catalog/catalog_writer.cpp @@ -299,12 +299,20 @@ PublisherLease CatalogWriter::acquire_lease(const std::string& holder) { require_owned_by_this_process(); const std::lock_guard serial(serial_); require_not_quarantined(); + const bool renewing = leases_->lease() != nullptr; try { return leases_->acquire(holder); } catch (const CatalogError&) { throw; } catch (const std::exception&) { - quarantine(); + // An unknown outcome only if a claim row may have been written: a + // renewal's, or a claim whose INSERT may have reached the server. One + // that failed before that -- its head read timed out, or could not + // connect -- wrote nothing, and a quarantine would only keep a writer + // with nothing to wait out from trying again. Deliberately unlike the + // Python oracle (clickhouse_catalog.py, acquire_publisher_lease), which + // quarantines on any error here. + if (renewing || leases_->claim_insert_sent()) quarantine(); throw; } } @@ -315,6 +323,12 @@ PublisherLease CatalogWriter::renew_lease() { return renew_for_publish(); } +void CatalogWriter::abandon_lease() { + require_owned_by_this_process(); + const std::lock_guard serial(serial_); + if (leases_->lease() != nullptr) quarantine(); +} + void CatalogWriter::release_lease() { require_owned_by_this_process(); const std::lock_guard serial(serial_); diff --git a/native/csrc/catalog/catalog_writer.h b/native/csrc/catalog/catalog_writer.h index e292c7e62..fb90fad5d 100644 --- a/native/csrc/catalog/catalog_writer.h +++ b/native/csrc/catalog/catalog_writer.h @@ -89,13 +89,25 @@ class CatalogWriter { PublisherLease renew_lease(); void release_lease(); const PublisherLease* held_lease() const { return leases_->lease(); } - // steady_clock ns: when the claim INSERT that stamped the held lease's row - // was sent -- the lease thread's last renewal, or a publish's -- or 0 - // while none is held. + // The held lease's timing, on the steady clock, 0 while none is held: when + // the claim INSERT that stamped its row was sent -- the lease thread's + // last renewal, or a publish's -- and the deadline every request made + // under it has to be answered by (lease_coordinator.h). Lock-free like + // held_lease(): the storage service reads the deadline before each request + // it sends while holding its lease lock. uint64_t lease_sent_ns() const { const PublisherLease* held = leases_->lease(); return held != nullptr ? held->sent_ns : 0; } + uint64_t lease_deadline_ns() const { + const PublisherLease* held = leases_->lease(); + return held != nullptr ? held->deadline_ns : 0; + } + // Gives up a lease whose deadline has passed unrenewed. Its row may still + // be live, and a statement of the pass that ran out of time may still be + // running, so it goes as an unknown outcome does: no tombstone, and + // quarantined for a TTL. + void abandon_lease(); uint64_t allocate_version(); uint64_t max_version(const std::string& table, const std::string& column) const; diff --git a/native/csrc/catalog/clickhouse_client.cpp b/native/csrc/catalog/clickhouse_client.cpp index 230233455..b25713dbe 100644 --- a/native/csrc/catalog/clickhouse_client.cpp +++ b/native/csrc/catalog/clickhouse_client.cpp @@ -121,6 +121,17 @@ std::string url_encode(const std::string& value) { return out; } +// The innermost RequestDeadline on this thread; each links to the one it +// nests in. +thread_local RequestDeadline* innermost_deadline = nullptr; + +// "60 s", "0.25 s": a timeout for a message. +std::string seconds_text(double seconds) { + char out[32]; + std::snprintf(out, sizeof(out), "%g s", seconds); + return out; +} + bool has_header_breaking_byte(const std::string& value) { return value.find_first_of(std::string("\r\n\0", 3)) != std::string::npos; } @@ -219,6 +230,42 @@ std::vector parse_tsv(const std::string& body) { } // namespace +uint64_t steady_now_ns() { + return static_cast( + std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count()); +} + +RequestDeadline::RequestDeadline(uint64_t deadline_ns, std::string bound) + : fixed_ns_(deadline_ns), bound_(std::move(bound)), + outer_(innermost_deadline) { + innermost_deadline = this; +} + +RequestDeadline::RequestDeadline(std::function deadline_ns, + std::string bound) + : moving_ns_(std::move(deadline_ns)), bound_(std::move(bound)), + outer_(innermost_deadline) { + innermost_deadline = this; +} + +RequestDeadline::~RequestDeadline() { innermost_deadline = outer_; } + +uint64_t RequestDeadline::current(std::string* bound) { + uint64_t tightest = 0; + for (const RequestDeadline* scope = innermost_deadline; scope != nullptr; + scope = scope->outer_) { + const uint64_t at = scope->moving_ns_ ? scope->moving_ns_() + : scope->fixed_ns_; + if (at != 0 && (tightest == 0 || at < tightest)) { + tightest = at; + if (bound != nullptr) *bound = scope->bound_; + } + } + return tightest; +} + void validate(const ClickHouseConnection& c) { if (c.scheme != "http" && c.scheme != "https") { throw ClickHouseError("clickhouse scheme must be \"http\" or \"https\""); @@ -431,7 +478,7 @@ std::vector ClickHouseClient::execute( } } - const auto perform = [&]() { + const auto perform = [&](long connect_ms, long request_ms) { Attempt attempt; CURL* curl = curl_easy_init(); if (curl == nullptr) throw ClickHouseError("libcurl init failed"); @@ -470,10 +517,8 @@ std::vector ClickHouseClient::execute( } // NOSIGNAL: timeouts must not use SIGALRM in a multi-threaded process. curl_easy_setopt(curl, CURLOPT_NOSIGNAL, 1L); - curl_easy_setopt(curl, CURLOPT_CONNECTTIMEOUT_MS, - timeout_ms(connection_.timeouts.connect_s)); - curl_easy_setopt(curl, CURLOPT_TIMEOUT_MS, - timeout_ms(connection_.timeouts.request_s)); + curl_easy_setopt(curl, CURLOPT_CONNECTTIMEOUT_MS, connect_ms); + curl_easy_setopt(curl, CURLOPT_TIMEOUT_MS, request_ms); attempt.code = curl_easy_perform(curl); curl_easy_getinfo(curl, CURLINFO_RESPONSE_CODE, &attempt.status); curl_easy_cleanup(curl); @@ -481,12 +526,64 @@ std::vector ClickHouseClient::execute( return attempt; }; + // Whether any attempt may have reached the server (ClickHouseError::sent). + bool sent = false; + std::string last_error; // the previous attempt's, for a retry not sent for (int number = 1;; ++number) { - const Attempt attempt = perform(); + // The client's timeouts, cut to the RequestDeadline in force: read + // afresh for every attempt, since its owner may have moved it. + long connect_ms = timeout_ms(connection_.timeouts.connect_s); + long request_ms = timeout_ms(connection_.timeouts.request_s); + std::string bound; + const uint64_t deadline_ns = RequestDeadline::current(&bound); + bool by_deadline = false; + if (deadline_ns != 0) { + const uint64_t now_ns = steady_now_ns(); + // Rounded down, so the attempt never outlasts the deadline. + const uint64_t left_ms = + deadline_ns > now_ns ? (deadline_ns - now_ns) / 1'000'000 : 0; + if (left_ms == 0) { + std::string error = + "Timeout: not sent, because " + bound + " had already passed"; + if (number > 1) { + error += "; the attempt before failed with: " + last_error; + } + throw ClickHouseError(error, true, sent); + } + if (left_ms < static_cast(request_ms)) { + request_ms = static_cast(left_ms); + by_deadline = true; + } + connect_ms = std::min(connect_ms, request_ms); + } + + const Attempt attempt = perform(connect_ms, request_ms); if (attempt.code == CURLE_OK && attempt.status == 200) { if (attempts != nullptr) *attempts = number; return parse_tsv(attempt.body); } + if (attempt.code == CURLE_OK || !never_connected(attempt.code)) { + sent = true; + } + if (attempt.code == CURLE_OPERATION_TIMEDOUT) { + // Never retried (above). Named, so whoever reads it knows which knob + // to turn: the deadline that cut the attempt short, or the client's + // own timeouts. + std::string error = std::string("curl: ") + + curl_easy_strerror(attempt.code); + if (!attempt.detail.empty()) error += ": " + attempt.detail; + error += by_deadline + ? " -- bounded by " + bound + : " -- bounded by the client's timeouts " + "(clickhouse_request_timeout_s = " + + seconds_text(connection_.timeouts.request_s) + + ", clickhouse_connect_timeout_s = " + + seconds_text(connection_.timeouts.connect_s) + ")"; + if (number > 1) { + error += " (attempt " + std::to_string(number) + ")"; + } + throw ClickHouseError(error, true, sent); + } std::string error; bool retry = false; if (attempt.code != CURLE_OK) { @@ -510,13 +607,23 @@ std::vector ClickHouseClient::execute( if (number > 1) { error += " (after " + std::to_string(number) + " attempts)"; } - throw ClickHouseError(error); + throw ClickHouseError(error, false, sent); } // 100 ms, doubling, capped at 1 s: enough for a restarting server or a // flapping connection, short beside the request timeout it adds to. const int shift = std::min(number - 1, 4); - std::this_thread::sleep_for(std::chrono::milliseconds( - std::min(100 << shift, 1000))); + const uint64_t backoff_ms = + static_cast(std::min(100 << shift, 1000)); + if (deadline_ns != 0 && + steady_now_ns() + backoff_ms * 1'000'000 >= deadline_ns) { + throw ClickHouseError( + error + " (after " + std::to_string(number) + + " attempt(s); not retried, because " + bound + + " leaves no time for another)", + false, sent); + } + last_error = error; + std::this_thread::sleep_for(std::chrono::milliseconds(backoff_ms)); } } diff --git a/native/csrc/catalog/clickhouse_client.h b/native/csrc/catalog/clickhouse_client.h index 185051731..595fa179a 100644 --- a/native/csrc/catalog/clickhouse_client.h +++ b/native/csrc/catalog/clickhouse_client.h @@ -11,6 +11,7 @@ #define DMI_CATALOG_CLICKHOUSE_CLIENT_H #include +#include #include #include #include @@ -27,8 +28,61 @@ using Row = std::vector; class ClickHouseError : public std::runtime_error { public: - explicit ClickHouseError(const std::string& what) - : std::runtime_error(what) {} + explicit ClickHouseError(const std::string& what, bool timed_out = false, + bool sent = true) + : std::runtime_error(what), timed_out_(timed_out), sent_(sent) {} + + // The request ran out of time: the client's request (or connect) timeout, + // or the RequestDeadline in force, ended it, or that deadline had already + // passed before it could be sent. The message names the bound. + bool timed_out() const { return timed_out_; } + // Whether the statement may have reached the server. False only when it + // cannot have: every attempt was refused its connection (or the name did + // not resolve), or the deadline had passed before one could go out. A + // write that failed with sent() false wrote nothing; with sent() true its + // outcome is unknown (a connect timeout counts as sent, conservatively). + bool sent() const { return sent_; } + + private: + bool timed_out_; + bool sent_; +}; + +// steady_clock nanoseconds: the clock a RequestDeadline is measured on. +uint64_t steady_now_ns(); + +// A deadline for every ClickHouse request made on the calling thread while +// the scope lives, on the steady clock. Each attempt's timeout (connect +// included) is cut to the time left, a request is not sent at all once the +// deadline has passed (a timed-out ClickHouseError, sent() false), and a +// retry's backoff never sleeps past it. Scopes nest; the tightest deadline +// in force wins. `bound` says what set the deadline -- the knobs behind it -- +// and a timeout it causes names it. +// +// The publisher lease is what uses it (lease_coordinator.h): while a lease is +// held, every request its holder makes has to be answered before the lease +// row can expire, not only the lease's own statements. +class RequestDeadline { + public: + // A fixed deadline, steady ns. + RequestDeadline(uint64_t deadline_ns, std::string bound); + // A deadline read afresh before every request attempt, so that its owner + // can move it while the scope lives (a lease that renews mid-pass). 0 + // means no deadline is in force at the moment. + RequestDeadline(std::function deadline_ns, std::string bound); + ~RequestDeadline(); + RequestDeadline(const RequestDeadline&) = delete; + RequestDeadline& operator=(const RequestDeadline&) = delete; + + // The tightest deadline in force on this thread, 0 if none; `bound`, when + // given, receives what set it. + static uint64_t current(std::string* bound = nullptr); + + private: + uint64_t fixed_ns_ = 0; + std::function moving_ns_; + std::string bound_; + RequestDeadline* outer_; }; // clickhouse-driver's client-side `%(name)s` substitution: one @@ -114,6 +168,10 @@ class ClickHouseClient { ClickHouseClient(const ClickHouseClient&) = delete; ClickHouseClient& operator=(const ClickHouseClient&) = delete; + double request_timeout_s() const { + return connection_.timeouts.request_s; + } + // Runs one statement with `%(name)s` parameters substituted client-side // and `settings` appended as URL parameters. Returns the parsed // FORMAT TSV rows (empty for writes). @@ -136,6 +194,13 @@ class ClickHouseClient { // Timeouts go to libcurl in whole milliseconds, rounded up, so a positive // timeout below 1 ms bounds the request at 1 ms rather than not at all. // + // Under a RequestDeadline the whole call, retries and backoff included, + // ends by that deadline: each attempt's timeouts are cut to the whole + // milliseconds left (rounded down, so never past it), no attempt starts + // with less than a millisecond left, and no backoff sleeps past it -- the + // last attempt's error is thrown instead, saying so. A timeout's message + // names the bound that ended it. + // // Reads also carry wait_end_of_query=1, so the server buffers the result // and an exception part-way through it arrives as an error status rather // than as a 200 whose truncated body would parse as rows. A URL setting: diff --git a/native/csrc/catalog/lease_coordinator.cpp b/native/csrc/catalog/lease_coordinator.cpp index d70cfa1c0..37779e000 100644 --- a/native/csrc/catalog/lease_coordinator.cpp +++ b/native/csrc/catalog/lease_coordinator.cpp @@ -1,7 +1,6 @@ #include "lease_coordinator.h" #include -#include #include #include #include @@ -10,15 +9,42 @@ namespace dmi_catalog { namespace { -uint64_t steady_ns() { - return static_cast( - std::chrono::duration_cast( - std::chrono::steady_clock::now().time_since_epoch()) - .count()); +// A Seconds setting from whole milliseconds. Whole seconds wherever the +// value allows -- what every server parses, and what publish_timeout_ns +// already requires -- rounded DOWN, so the server's cap never exceeds the +// client's deadline. Only a time under a second goes out as a fraction, +// which current servers parse, for max_execution_time and +// lock_acquire_timeout alike (checked on 25.12). Never "0": ClickHouse reads +// a zero max_execution_time as no limit at all. +std::string seconds_setting(uint64_t ms) { + if (ms >= 1000) return std::to_string(ms / 1000); + ms = std::max(ms, 1); + char out[8]; + std::snprintf(out, sizeof(out), "0.%03u", static_cast(ms)); + std::string text(out); + while (text.back() == '0') text.pop_back(); + return text; } } // namespace +const char* const kLeaseDeadlineBound = + "the lease deadline (lease_ttl_s, less clock_skew_s and a 0.1 s margin, " + "after the claim that stamped the lease row was sent; " + "clickhouse_request_timeout_s caps each request as well)"; + +uint64_t lease_deadline_ns(uint64_t sent_ns, uint64_t lease_ttl_ns, + uint64_t clock_skew_ns) { + const uint64_t spent = clock_skew_ns + kLeaseDeadlineMarginNs; + return lease_ttl_ns > spent ? sent_ns + (lease_ttl_ns - spent) : sent_ns; +} + +uint64_t renewal_window_ns(uint64_t lease_ttl_ns, uint64_t clock_skew_ns) { + const uint64_t spent = clock_skew_ns + kLeaseDeadlineMarginNs; + const uint64_t half = lease_ttl_ns / 2; + return half > spent ? half - spent : 0; +} + std::string new_uuid_v4() { static std::mt19937_64 rng(std::random_device{}()); uint64_t a = rng(), b = rng(); @@ -40,14 +66,72 @@ LeaseCoordinator::LeaseCoordinator( : client_(std::move(client)), config_(std::move(config)) { table_ = "`" + config_.database + "`.`" + config_.table_prefix + "_publisher_lease`"; + const double request_ns = client_->request_timeout_s() * 1e9; + claim_bound_ns_ = std::max( + request_ns < static_cast(config_.lease_ttl_ns / 3) + ? static_cast(request_ns) + : config_.lease_ttl_ns / 3, + 1'000'000); + claim_bound_text_ = + "the bound on each request of a claim made without a live lease, " + "min(clickhouse_request_timeout_s, lease_ttl_s / 3) = " + + std::to_string(claim_bound_ns_ / 1'000'000) + " ms"; } -std::map LeaseCoordinator::quorum_write() const { - if (!config_.insert_quorum.has_value()) return {}; - return {{"insert_quorum", std::to_string(*config_.insert_quorum)}, - {"insert_quorum_parallel", "0"}, - {"insert_quorum_timeout", - std::to_string(config_.publish_timeout_ns / 1'000'000)}}; +std::vector LeaseCoordinator::run( + const std::string& query, const Params& params, + std::map settings, bool write) const { + // Held, and its deadline still ahead: that deadline, shared by every + // request until the lease renews. Otherwise each request gets the claim + // bound from when it starts -- with no lease, and with one whose deadline + // has passed, whose row can no longer be counted on to keep rivals out. + // A request made under such a lease is a claim like any other, decided by + // the protocol's own reads: a renewal that meets a successor is refused, + // and a publish is fenced out. Refusing to send it at all would turn those + // known outcomes into unknown ones. What must not happen is a holder going + // on as though it still held the lease, and the storage service abandons + // one before it makes another request (storage_service.h). + const uint64_t now = steady_now_ns(); + const bool live = lease_.has_value() && lease_->deadline_ns > now; + const RequestDeadline deadline( + live ? lease_->deadline_ns : now + claim_bound_ns_, + live ? std::string(kLeaseDeadlineBound) : claim_bound_text_); + if (write) add_write_caps(&settings); + return client_->execute(query, params, settings); +} + +void LeaseCoordinator::add_write_caps( + std::map* settings) const { + // A lease INSERT the client gave up on (a timeout, so an unknown outcome) + // must not land afterwards: a claim row stamped then outlives the + // quarantine meant to cover it. So the server gets the time left before + // the request's deadline -- the tightest in force, as the client computes + // it -- and abandons the statement then: max_execution_time for running + // it, lock_acquire_timeout for waiting on the table lock before it starts, + // and throw, not break, since break would insert what had been read so + // far. The quorum wait is bounded by insert_quorum_timeout alone, so that + // is capped too, as well as by publish_timeout as before: past the + // deadline nobody is listening. + // + // What the caps do not cover: ClickHouse checks max_execution_time only at + // designated points while the pipeline runs, so the part commit can + // overrun it, and its clock starts when the server starts the query, not + // when the client sent it -- a request held up in transit can still land + // up to that delay after the client gave up. + const uint64_t deadline = RequestDeadline::current(); // run() set one + const uint64_t now = steady_now_ns(); + // 0 when the deadline has passed; execute() then sends nothing. + const uint64_t left_ms = deadline > now ? (deadline - now) / 1'000'000 : 0; + if (config_.insert_quorum.has_value()) { + (*settings)["insert_quorum"] = std::to_string(*config_.insert_quorum); + (*settings)["insert_quorum_parallel"] = "0"; + (*settings)["insert_quorum_timeout"] = std::to_string(std::max( + std::min(config_.publish_timeout_ns / 1'000'000, left_ms), + 1)); + } + (*settings)["max_execution_time"] = seconds_setting(left_ms); + (*settings)["lock_acquire_timeout"] = seconds_setting(left_ms); + (*settings)["timeout_overflow_mode"] = "throw"; } PublisherLease LeaseCoordinator::acquire(const std::string& holder) { @@ -78,13 +162,13 @@ PublisherLease LeaseCoordinator::renew() { void LeaseCoordinator::release() { const PublisherLease* held = lease(); if (held == nullptr) return; - client_->execute(release_statement(), - {{"term", held->term}, - {"lease_id", held->lease_id}, - {"holder", held->holder}}, - // A deciding WRITE like the claim: the successor's head - // read is what this row is written for. - quorum_write()); + // A deciding WRITE like the claim: the successor's head read is what this + // row is written for. + run(release_statement(), + {{"term", held->term}, + {"lease_id", held->lease_id}, + {"holder", held->holder}}, + {}, true); lease_.reset(); } @@ -110,23 +194,34 @@ PublisherLease LeaseCoordinator::claim_contested( PublisherLease LeaseCoordinator::claim_with_rival( const std::string& holder, const std::string& lease_id, std::optional rival_lease_id) { + claim_insert_sent_ = false; const LeaseHead current = head(); reject_live(current, lease_id); const uint64_t term = current.term + 1; // Taken before the INSERT goes out, so never after the server stamps the - // row: the renewal schedule counts from here. - const uint64_t sent_ns = steady_ns(); - insert(term, lease_id, holder); + // row: the new lease's deadline counts from here. + const uint64_t sent_ns = steady_now_ns(); + claim_insert_sent_ = true; + try { + insert(term, lease_id, holder); + } catch (const ClickHouseError& exc) { + // Nothing reached the server when no attempt connected, or when the + // deadline had passed before the INSERT could go out. + claim_insert_sent_ = exc.sent(); + throw; + } if (rival_lease_id.has_value()) { // The contested-claim scenario: a rival row lands between the // claimant's INSERT and its read-back, the way the Python live suite // injects it through a client wrapper. Same term, long TTL. insert(term, *rival_lease_id, "rival", 600'000'000'000ull); } - const std::vector rows = client_->execute( + // Under the old lease's deadline on a renewal: its row is what keeps + // rivals out until this one is confirmed. + const std::vector rows = run( "SELECT toString(lease_id), acquired_at_ns, expires_at_ns " "FROM " + table_ + " WHERE term = %(term)s", - {{"term", term}}, deciding_read()); + {{"term", term}}, deciding_read(), false); std::set owners; for (const Row& row : rows) owners.insert(row[0]); if (owners == std::set{lease_id}) { @@ -144,7 +239,9 @@ PublisherLease LeaseCoordinator::claim_with_rival( term, lease_id, holder, parse_u64_field(rows[0][1], "lease acquisition"), parse_u64_field(rows[0][2], "lease expiry"), - sent_ns}; + sent_ns, + lease_deadline_ns(sent_ns, config_.lease_ttl_ns, + config_.clock_skew_ns)}; return *lease_; } lease_.reset(); @@ -155,12 +252,12 @@ PublisherLease LeaseCoordinator::claim_with_rival( LeaseHead LeaseCoordinator::head() const { const std::string table = table_; - const std::vector rows = client_->execute( + const std::vector rows = run( "SELECT term, toString(lease_id), any(holder), min(expires_at_ns), " "toUnixTimestamp64Nano(now64(9)) FROM " + table + " " "WHERE term = (SELECT max(term) FROM " + table + ") " "GROUP BY term, lease_id ORDER BY lease_id DESC", - {}, deciding_read()); + {}, deciding_read(), false); if (rows.empty()) return LeaseHead{}; LeaseHead out; out.term = parse_u64_field(rows[0][0], "lease term"); @@ -197,12 +294,12 @@ bool LeaseCoordinator::fence_eval(const std::string& lease_id, // A deciding read: the answer decides whether the fence admits, and the // fence's head subquery read from a replica behind on the lease table // would admit or deny on stale state. - const std::vector rows = client_->execute( + const std::vector rows = run( "SELECT " + fence(), {{"lease_id", lease_id}, {"publish_timeout_ns", publish_timeout_ns}, {"clock_skew_ns", clock_skew_ns}}, - deciding_read()); + deciding_read(), false); return !rows.empty() && rows[0][0] == "1"; } @@ -226,8 +323,7 @@ void LeaseCoordinator::reject_if_gone() const { void LeaseCoordinator::insert(uint64_t term, const std::string& lease_id, const std::string& holder, std::optional ttl_ns) const { - client_->execute( - "INSERT INTO " + table_ + " " + run("INSERT INTO " + table_ + " " "(term, lease_id, holder, acquired_at_ns, expires_at_ns) " "SELECT toUInt64(%(term)s), toUUID(%(lease_id)s), %(holder)s, " "now_ns, now_ns + toUInt64(%(ttl_ns)s) " @@ -236,7 +332,7 @@ void LeaseCoordinator::insert(uint64_t term, const std::string& lease_id, {"lease_id", lease_id}, {"holder", holder}, {"ttl_ns", ttl_ns.value_or(config_.lease_ttl_ns)}}, - quorum_write()); + {}, true); } void LeaseCoordinator::reject_live(const LeaseHead& head, diff --git a/native/csrc/catalog/lease_coordinator.h b/native/csrc/catalog/lease_coordinator.h index 271b05f77..5d402c725 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -20,11 +20,67 @@ #include #include #include +#include #include "clickhouse_client.h" namespace dmi_catalog { +// The deadline on the publisher lease's requests. +// +// A lease row lives lease_ttl_ns from when the server stamps it, and a rival +// whose clock runs clock_skew_ns ahead sees it expire that much early. The +// server stamps it no earlier than the claim INSERT was sent, so a writer can +// count on its row keeping rivals out until +// +// lease deadline = claim INSERT sent + lease_ttl_ns - clock_skew_ns - 0.1 s +// +// on its own steady clock, the 0.1 s (kLeaseDeadlineMarginNs) covering the +// time between a request failing and the writer saying so. Every request +// made while the lease is held has to be answered by then: the lease's own +// (a renewal's head read, claim INSERT and read-back, the release tombstone) +// here, and in the storage service every catalog request made under its +// lease lock (storage_service.h), since the lease cannot renew until that +// lock is let go. A renewal that cannot finish in time therefore fails, and +// quarantines the writer, while its row still keeps rivals out -- however +// the time is spread across its requests, so one slow but healthy request +// may use all of it. The deadline moves with each confirmed renewal, a +// publish's included, since each claim that stamps a row restarts it. +// +// A claim made without a lease has no row to protect yet. Each of its +// requests is bounded by min(the client's request timeout, lease_ttl_ns / +// 3): long enough for a slow catalog, short enough that a claim which hangs +// fails well inside a TTL. So is a request made under a lease whose deadline +// has already passed (run() says why it is still sent). +// +// The lease INSERTs carry the time left before their deadline to the server +// as max_execution_time and lock_acquire_timeout, and cap a quorum wait by +// it, so the server abandons a claim no later than the client does. +constexpr uint64_t kLeaseDeadlineMarginNs = 100'000'000ull; + +// The deadline of a lease whose claim INSERT was sent at `sent_ns` (steady +// clock); `sent_ns` itself when the skew and margin leave nothing. +uint64_t lease_deadline_ns(uint64_t sent_ns, uint64_t lease_ttl_ns, + uint64_t clock_skew_ns); + +// How long a renewal has between when it starts, at the latest, and the +// lease deadline it must finish by. The storage service renews a third of +// the TTL after the claim that stamped the row was sent and looks every +// sixth, so a renewal starts within lease_ttl_ns / 2 of that send: +// +// window = lease_ttl_ns / 2 - clock_skew_ns - kLeaseDeadlineMarginNs +// +// 0 when the skew leaves no time at all. +uint64_t renewal_window_ns(uint64_t lease_ttl_ns, uint64_t clock_skew_ns); + +// The storage service refuses a skew whose renewal window is shorter than +// this (storage_service.cpp): below it a renewal cannot be expected to +// finish against a real server. +constexpr uint64_t kMinimumRenewalWindowNs = 200'000'000ull; + +// What bounds a request made under the lease, for a timeout's message. +extern const char* const kLeaseDeadlineBound; + struct LeaseConfig { std::string database; std::string table_prefix; @@ -41,10 +97,10 @@ struct PublisherLease { std::string holder; uint64_t acquired_at_ns = 0; uint64_t expires_at_ns = 0; - // steady_clock ns: when the claim INSERT that stamped this row was sent. - // The server stamps the row no earlier, so it lives at least lease_ttl_ns - // past this on the claimant's own clock. + // steady_clock ns: when the claim INSERT that stamped this row was sent, + // and the lease deadline that follows from it (lease_deadline_ns). uint64_t sent_ns = 0; + uint64_t deadline_ns = 0; }; struct LeaseHead { @@ -93,6 +149,14 @@ class LeaseCoordinator { return lease_.has_value() ? &*lease_ : nullptr; } uint64_t ttl_ns() const { return config_.lease_ttl_ns; } + // The bound on each request of a claim made without a live lease: + // min(request timeout, lease_ttl_ns / 3). + uint64_t claim_bound_ns() const { return claim_bound_ns_; } + // Whether the last claim's INSERT may have reached the server. One that + // failed before it -- its head read timed out, say -- or whose INSERT + // never connected, or was not sent because its deadline had passed, + // wrote nothing, whatever it failed with. + bool claim_insert_sent() const { return claim_insert_sent_; } PublisherLease acquire(const std::string& holder); PublisherLease renew(); @@ -119,10 +183,19 @@ class LeaseCoordinator { const std::string& holder, std::optional ttl_ns = std::nullopt) const; void reject_live(const LeaseHead& head, const std::string& lease_id); - std::map quorum_write() const; + // Runs one lease statement under its deadline (see above): the held + // lease's while that is still ahead, the claim bound from now otherwise. + // A lease INSERT (`write`) also carries the time left to the server. + std::vector run(const std::string& query, const Params& params, + std::map settings, + bool write) const; + void add_write_caps(std::map* settings) const; std::shared_ptr client_; LeaseConfig config_; + uint64_t claim_bound_ns_ = 0; + std::string claim_bound_text_; // claim_bound_ns_, for a timeout's message + bool claim_insert_sent_ = false; std::optional lease_; std::string table_; }; diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index 2dabdde10..ae9f85e8a 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -61,13 +61,49 @@ bool is_lease_refusal(const CatalogError& exc) { // The lease thread's tick, which is also the retry interval for a claim // another holder refused: a sixth of the TTL, so a renewal due at ttl/3 is -// never more than a tick late. +// never more than a tick late. renewal_window_ns (lease_coordinator.h) takes +// the least time a renewal has from this schedule -- it starts within ttl/2 +// of the claim that stamped the row -- so change one and the other must +// follow. uint64_t lease_tick_ns(uint64_t ttl_ns) { return std::max(ttl_ns / 6, 10'000'000ull); } +std::string seconds_text(uint64_t ns) { + char out[32]; + std::snprintf(out, sizeof(out), "%g s", static_cast(ns) / 1e9); + return out; +} + } // namespace +class CaptureStorageService::LeaseScope { + public: + explicit LeaseScope(CaptureStorageService* service) + : service_(service), + lock_(service->lease_mutex_), + deadline_([service] { return service->writer_.lease_deadline_ns(); }, + kLeaseDeadlineBound) { + service_->abandon_lease_if_expired(); + } + + ~LeaseScope() { + try { + service_->abandon_lease_if_expired(); + service_->publish_lease_state(); + } catch (...) { + } + } + + LeaseScope(const LeaseScope&) = delete; + LeaseScope& operator=(const LeaseScope&) = delete; + + private: + CaptureStorageService* service_; + std::unique_lock lock_; + RequestDeadline deadline_; // after lock_: released before it +}; + CaptureStorageService::CaptureStorageService(StorageServiceConfig config) : config_(std::move(config)), s3_(config_.s3), @@ -83,6 +119,27 @@ CaptureStorageService::CaptureStorageService(StorageServiceConfig config) if (config_.uploader.store_id.empty()) { throw std::invalid_argument("storage service: uploader.store_id is required"); } + // A renewal that fails must fail while its row still keeps rivals out, + // so it has until the lease deadline (lease_coordinator.h). A skew bound + // that leaves it too little time is refused here rather than turned into + // renewals that time out against a healthy server. + const uint64_t window_ns = renewal_window_ns(config_.writer.lease_ttl_ns, + config_.writer.clock_skew_ns); + if (window_ns < kMinimumRenewalWindowNs) { + throw std::invalid_argument( + "storage service: clock_skew_ns leaves a lease renewal no time to " + "finish while its row is live. A renewal starts up to lease_ttl_ns " + "/ 2 after the claim that stamped the row was sent, and has to be " + "answered by lease_ttl_ns less clock_skew_ns and a " + + std::to_string(kLeaseDeadlineMarginNs / 1'000'000) + + " ms margin after it: " + std::to_string(window_ns / 1'000'000) + + " ms, under the " + + std::to_string(kMinimumRenewalWindowNs / 1'000'000) + + " ms minimum. Keep clock_skew_ns at most lease_ttl_ns / 2 - " + + std::to_string((kMinimumRenewalWindowNs + kLeaseDeadlineMarginNs) / + 1'000'000) + + " ms, or raise lease_ttl_ns"); + } std::string error; if (dmi_store::Spool::Open({config_.spool_root, config_.spool_max_bytes}, &spool_, &error) != dmi_store::SpoolStatus::kOk) { @@ -106,7 +163,7 @@ void CaptureStorageService::start() { CatalogSchema(clickhouse_, config_.writer.database, config_.writer.table_prefix) .ensure(&writer_.leases(), config_.schema_retry_sleep_ns); { - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); acquire_lease_at_start(); // throws kHeld if another publisher keeps it } @@ -121,7 +178,7 @@ void CaptureStorageService::start() { std::string error; if (spool_.Recover(&recovered, &error) != dmi_store::SpoolStatus::kOk) { try { - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); if (writer_.held_lease() != nullptr) writer_.release_lease(); } catch (...) { } @@ -141,7 +198,7 @@ void CaptureStorageService::start() { } catch (const CatalogError& exc) { if (is_lease_refusal(exc)) { try { - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); if (writer_.held_lease() != nullptr) writer_.release_lease(); } catch (...) { } @@ -160,8 +217,7 @@ void CaptureStorageService::start() { kick_ = false; } { - std::lock_guard lease(lease_mutex_); - publish_lease_state(); + LeaseScope lease(this); // publishes the lease state } { std::lock_guard lock(state_mutex_); @@ -188,7 +244,7 @@ void CaptureStorageService::stop() { // live until the TTL keeps a successor out of that window. bool released = false; try { - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); if (writer_.held_lease() != nullptr) { writer_.release_lease(); released = true; @@ -280,7 +336,7 @@ CaptureStorageService::CycleOutcome CaptureStorageService::run_cycle() { // nothing either: whatever it uploaded it could only owe, in memory. bool catalog = false; { - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); catalog = ensure_publisher_lease(); } // Indexes refs, keeping whatever does not index owed: it is already gone @@ -438,7 +494,7 @@ void CaptureStorageService::index_bounded(std::vector refs, // (renew_lease_if_due), which only a claim that confirmed moves -- a // pass that published nothing, over packs already committed, renewed // nothing. - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); result = indexer_.index(batch); } catch (const CatalogError& exc) { if (exc.kind() == CatalogError::Kind::kBatchTooLarge && batch.size() > 1) { @@ -535,7 +591,7 @@ void CaptureStorageService::reconcile() { if (packs.empty()) continue; std::set committed; { - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); committed = writer_.committed_pack_ids(identities); } @@ -608,7 +664,7 @@ void CaptureStorageService::keep_lease() { std::lock_guard lock(state_mutex_); if (failure_) return; } - std::lock_guard lease(lease_mutex_); + LeaseScope lease(this); // publishes the lease state when done if (writer_.held_lease() == nullptr) { ensure_publisher_lease(); continue; @@ -627,8 +683,8 @@ void CaptureStorageService::keep_lease() { // An unknown outcome: the writer quarantined itself and dropped the // lease. ensure_publisher_lease() replaces it after the window. record_error(std::string("lease renewal failed: ") + exc.what()); + note_lease_failure(exc); } - publish_lease_state(); } } @@ -638,16 +694,64 @@ void CaptureStorageService::renew_lease_if_due() { // its fenced statements -- as the writer records it, so nothing but a // confirmed claim moves the schedule. The lease thread looks every sixth // of the TTL, so with the lease lock free a renewal starts within half the - // TTL of that send, and the row has the other half left. + // TTL of that send, and has until the lease deadline to be answered: the + // renewal window the constructor checks (lease_coordinator.h). A stretch + // under the lease lock delays it, but every request in such a stretch is + // bounded by the same deadline. A failed renewal costs the lease at once: a refusal drops it in the coordinator, and any other + // error quarantines the writer (renew_for_publish). const uint64_t ttl = config_.writer.lease_ttl_ns; const uint64_t sent = writer_.lease_sent_ns(); if (ttl == 0 || sent == 0 || steady_ns() - sent < ttl / 3) return; writer_.renew_lease(); held_elsewhere_since_ns_ = 0; + note_lease_success(); std::lock_guard lock(state_mutex_); ++state_.lease_renewals; } +void CaptureStorageService::abandon_lease_if_expired() { + const uint64_t deadline = writer_.lease_deadline_ns(); + if (deadline == 0 || steady_ns() < deadline) return; + writer_.abandon_lease(); + record_error(std::string("publisher lease abandoned: it was not renewed " + "by ") + kLeaseDeadlineBound); +} + +void CaptureStorageService::note_lease_failure(const std::exception& failure) { + const auto* error = dynamic_cast(&failure); + if (error == nullptr || !error->timed_out()) return; + ++lease_timeouts_; + std::string message; + if (lease_timeouts_ >= 3) { + // The knobs first: last_error keeps only its first 512 bytes. + const uint64_t claim_bound = writer_.leases().claim_bound_ns(); + message = + std::to_string(lease_timeouts_) + + " publisher lease claims or renewals have timed out since one last " + "succeeded. Requests made under the lease have until its deadline, " + "lease_ttl_s (" + + seconds_text(config_.writer.lease_ttl_ns) + ") less clock_skew_s (" + + seconds_text(config_.writer.clock_skew_ns) + ") and a " + + seconds_text(kLeaseDeadlineMarginNs) + + " margin after the claim that stamped its row was sent; each request " + "of a claim made without one has min(clickhouse_request_timeout_s, " + "lease_ttl_s / 3) = " + seconds_text(claim_bound) + + ". A catalog this slow needs a longer lease_ttl_s. The latest: " + + error->what(); + record_error(message); + } + std::lock_guard lock(state_mutex_); + state_.lease_timeouts = lease_timeouts_; + state_.lease_timeout_error = message.substr(0, 1024); +} + +void CaptureStorageService::note_lease_success() { + lease_timeouts_ = 0; + std::lock_guard lock(state_mutex_); + state_.lease_timeouts = 0; + state_.lease_timeout_error.clear(); +} + void CaptureStorageService::acquire_lease_at_start() { // A crashed predecessor's lease stays live for up to its TTL. Waiting it // out here turns a restart inside that window into a short delay instead @@ -659,6 +763,7 @@ void CaptureStorageService::acquire_lease_at_start() { while (true) { try { writer_.acquire_lease(config_.holder); + note_lease_success(); return; } catch (const CatalogError& exc) { if (!is_lease_refusal(exc) || config_.start_lease_wait_ns == 0) throw; @@ -673,6 +778,32 @@ void CaptureStorageService::acquire_lease_at_start() { } std::this_thread::sleep_for( std::chrono::nanoseconds(std::min(poll, deadline - now))); + } catch (const ClickHouseError& exc) { + // A claim that timed out -- a cold catalog's first reads can outlast + // the claim bound -- is retried within the same wait. One that wrote + // nothing (its head read timed out) goes again at once; one whose + // INSERT may have landed quarantined the writer for a TTL, which is + // waited out when it ends inside the wait. Any other error fails + // start() as before. + record_error(std::string("publisher lease claim at start failed: ") + + exc.what()); + note_lease_failure(exc); + if (!exc.timed_out() || config_.start_lease_wait_ns == 0) throw; + uint64_t resume = steady_ns(); + uint64_t until = 0; + if (writer_.quarantined(&until)) resume = std::max(resume, until); + if (resume >= deadline) { + throw ClickHouseError( + "storage service: the publisher lease claim timed out, and " + "start_lease_wait_ns (" + + std::to_string(config_.start_lease_wait_ns / 1'000'000) + + " ms) leaves no time to try again: " + exc.what(), + true, exc.sent()); + } + const uint64_t now = steady_ns(); + if (resume > now) { + std::this_thread::sleep_for(std::chrono::nanoseconds(resume - now)); + } } } } @@ -706,12 +837,21 @@ bool CaptureStorageService::ensure_publisher_lease() { publish_lease_state(); return false; } catch (const std::exception& exc) { - // Unknown outcome again: the writer quarantined itself for a TTL. + // An unknown outcome if the claim INSERT may have reached the server: + // the writer quarantined itself for a TTL. A claim that wrote nothing + // (its head read timed out or could not connect) is not quarantined, + // and goes again a tick from now, so that flush()'s fast cycles do not + // hammer a catalog that cannot answer. record_error(std::string("publisher lease acquisition failed: ") + exc.what()); + note_lease_failure(exc); + if (!writer_.quarantined()) { + next_claim_ns_ = steady_ns() + lease_tick_ns(config_.writer.lease_ttl_ns); + } publish_lease_state(); return false; } + note_lease_success(); held_elsewhere_since_ns_ = 0; next_claim_ns_ = 0; { diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index 0b3d0fc49..06be119e6 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -38,6 +38,20 @@ // (clickhouse_catalog.py, publish_snapshot). Only a foreign lease that stays // live for 2 x TTL is fatal: the service stops (snapshot().failed), writes // one line to stderr, and flush() rethrows the refusal naming the holder. +// +// Bounded by the lease. Every catalog request the service makes while it +// holds the lease -- the renewal's own, and every one an index pass or a +// reconcile sends under the lease lock -- has to be answered by the lease +// deadline (lease_coordinator.h), since the lease cannot renew while that +// lock is held: so a catalog that stops answering fails the stretch, and the +// lease quarantines, while its row still keeps rivals out. A lease whose +// deadline passes unrenewed is abandoned, never reported held (LeaseScope). +// Claims made with no +// lease are bounded by min(request timeout, lease_ttl / 3) per request; a +// claim that times out at start() is retried until start_lease_wait_ns ends, +// and lease requests that keep timing out say which knobs bound them +// (snapshot().lease_timeout_error). The constructor refuses a clock skew +// that leaves a renewal too little time to finish. #pragma once #include @@ -151,6 +165,12 @@ struct StorageServiceSnapshot { // steady_clock ns at which the quarantine ends; 0 when not quarantined. uint64_t quarantined_until_ns = 0; uint64_t lease_reacquisitions = 0; // fresh leases taken after a loss + // Lease claims and renewals that timed out since one last succeeded. + // From the third on, lease_timeout_error says so and names the knobs that + // bound them (it is last_error too, when it happens); both clear once a + // claim or renewal succeeds. + uint64_t lease_timeouts = 0; + std::string lease_timeout_error; std::string last_error; }; @@ -162,9 +182,10 @@ class CaptureStorageService { CaptureStorageService& operator=(const CaptureStorageService&) = delete; // Ensure the catalog schema, take the publisher lease (waiting up to - // start_lease_wait_ns for another holder's to expire), sweep the spool, - // reconcile once, then start the background cycle. Throws if the lease is - // still held by another publisher when the wait ends. + // start_lease_wait_ns for another holder's to expire, or for a claim that + // timed out to go through), sweep the spool, reconcile once, then start + // the background cycle. Throws if the lease is still held by another + // publisher when the wait ends, or its claim still times out. void start(); // Run cycles until one finds the spool empty with every uploaded pack @@ -191,6 +212,14 @@ class CaptureStorageService { bool failed = true; // an upload or index failed, or the cycle threw }; + // Holds lease_mutex_ for a stretch of catalog work, and bounds every + // request the thread makes meanwhile by the held lease's deadline -- read + // afresh per request, so a renewal inside the stretch extends it at once. + // A lease whose deadline has passed is abandoned on the way in and on the + // way out, so it is neither used nor reported held; the lease state is + // published on the way out. Every use of writer_'s lease goes through one. + class LeaseScope; + void loop(); CycleOutcome run_cycle(); // requires cycle_mutex_ // Indexes refs in bounded batches, appending every ref that did not index @@ -200,7 +229,16 @@ class CaptureStorageService { void reconcile(); void keep_lease(); // the lease thread's body void renew_lease_if_due(); // requires lease_mutex_ - // Takes the lease at start(), waiting for an expiring predecessor. + // Gives up a held lease whose deadline has passed. Requires lease_mutex_. + void abandon_lease_if_expired(); + // A lease claim or renewal failed (call from its catch block): one that + // timed out counts towards lease_timeouts. Requires lease_mutex_. + void note_lease_failure(const std::exception& failure); + // A claim or renewal succeeded: clears the timeout count. Requires + // lease_mutex_. + void note_lease_success(); + // Takes the lease at start(), waiting for an expiring predecessor or + // retrying a claim that timed out. void acquire_lease_at_start(); // requires lease_mutex_ // Whether the writer holds a lease, taking a fresh one when it has none // and is no longer quarantined. Never throws. Requires lease_mutex_. @@ -227,8 +265,12 @@ class CaptureStorageService { // a cycle is still in flight. std::timed_mutex cycle_mutex_; // Serialises every use of writer_'s lease: the lease thread renews it - // while cycles publish. Taken inside cycle_mutex_, never the other way. + // while cycles publish. Taken inside cycle_mutex_, never the other way, + // and only through a LeaseScope. std::mutex lease_mutex_; + // Lease claims and renewals timed out since the last that succeeded. + // Guarded by lease_mutex_. + uint64_t lease_timeouts_ = 0; // When a claim or renewal was first refused by another holder since the // lease was last held; 0 while none has been. Guarded by lease_mutex_. uint64_t held_elsewhere_since_ns_ = 0; diff --git a/src/dmi/storage/native_capture.py b/src/dmi/storage/native_capture.py index aed635898..57857db17 100644 --- a/src/dmi/storage/native_capture.py +++ b/src/dmi/storage/native_capture.py @@ -85,6 +85,16 @@ def _ns(seconds: float) -> int: # once the publish statement cap and the skew bound are spent. _FENCE_MARGIN_NS = 100_000_000 +# The native kLeaseDeadlineMarginNs and kMinimumRenewalWindowNs +# (native/csrc/catalog/lease_coordinator.h), see _validate_lease. +_LEASE_DEADLINE_MARGIN_NS = 100_000_000 +_MINIMUM_RENEWAL_WINDOW_NS = 200_000_000 + + +def _renewal_window_ns(ttl_ns: int, skew_ns: int) -> int: + """renewal_window_ns from native/csrc/catalog/lease_coordinator.h.""" + return max(ttl_ns // 2 - skew_ns - _LEASE_DEADLINE_MARGIN_NS, 0) + # The sink's admission policies (native/csrc/sink/pack_sink.h Overload). SINK_OVERLOAD_POLICIES = ("block", "drop_newest") @@ -231,7 +241,13 @@ class NativeCaptureStorageConfig: clickhouse_reader_user: str = "" clickhouse_reader_password: str = field(default="", repr=False) # Every catalog request is bounded, so a server that stops answering - # cannot hold a flush, a publish or the lease renewal indefinitely. + # cannot hold a flush, a publish or the lease renewal indefinitely. While + # the service holds the publisher lease, its requests are bounded tighter + # still, by the lease deadline -- lease_ttl_s less clock_skew_s and 0.1 s + # after the claim that stamped the lease row was sent -- so a renewal or + # an index pass that cannot finish fails while the row still keeps + # rivals out; each request of a claim made without a lease has + # min(clickhouse_request_timeout_s, lease_ttl_s / 3). clickhouse_connect_timeout_s: float = 10.0 clickhouse_request_timeout_s: float = 60.0 database: str = "default" @@ -265,7 +281,9 @@ class NativeCaptureStorageConfig: lease_ttl_s: float = 15.0 # The server-side cap on each fenced publish statement, whole seconds. publish_timeout_s: float = 5.0 - # The bound on host clock disagreement across a replicated catalog. + # The bound on host clock disagreement across a replicated catalog. At + # most lease_ttl_s / 2 - 0.3 s: a renewal must have time to fail while a + # rival whose clock runs ahead still sees the row live. clock_skew_s: float = 0.0 # How long start() waits for a predecessor's lease to expire before # failing with it held. None waits lease_ttl_s + publish_timeout_s + @@ -370,6 +388,23 @@ def _validate_lease(self) -> None: "lease_ttl_s must exceed publish_timeout_s + clock_skew_s by " "at least 0.1 s, or a publish statement can still be running " "when its lease becomes takeable") + # The native service's rule (storage_service.cpp): a renewal starts + # up to lease_ttl_s / 2 after the claim that stamped the lease row + # was sent, and has to be answered by the lease deadline, lease_ttl_s + # less clock_skew_s and 0.1 s after that send, so that a renewal + # that fails does so while its row is still live. + window = _renewal_window_ns(_ns(self.lease_ttl_s), + _ns(self.clock_skew_s)) + if window < _MINIMUM_RENEWAL_WINDOW_NS: + raise ValueError( + "clock_skew_s leaves a lease renewal no time to finish while " + "its row is live: a renewal starts up to lease_ttl_s / 2 " + "after the claim that stamped the row was sent, and has to be " + "answered by lease_ttl_s - clock_skew_s - 0.1 s after it, " + f"which leaves {window / 1e6:.1f} ms, under the " + f"{_MINIMUM_RENEWAL_WINDOW_NS // 1_000_000} ms minimum. Keep " + "clock_skew_s at most lease_ttl_s / 2 - 0.3 s, or raise " + "lease_ttl_s") def _lease_native(self) -> dict[str, int]: wait = self.start_lease_wait_s @@ -553,7 +588,8 @@ def start(self) -> None: """Ensure the catalog schema, take the lease, sweep the spool. Waits up to ``start_lease_wait_s`` for another holder's lease to - expire, then raises naming the holder. + expire, then raises naming the holder. A claim that times out is + retried within the same wait. """ self._service.start() diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 61904e36f..c0f85773b 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -22,6 +22,7 @@ import base64 import json +import re import socket import subprocess import threading @@ -276,7 +277,11 @@ def test_the_reference_reader_sees_the_same_captures(fake_s3, tmp_path): class _Switch: """A TCP forwarder in front of ClickHouse's HTTP port that can be cut - (connections refused) or stalled (connections accepted, never answered).""" + (connections refused), stalled (connections accepted, never answered), + made to stall only the requests a predicate picks, or to hold the first + request a predicate picks back for a while. Every + native client opens one connection per request, so one request is one + connection here.""" def __init__(self, host: str, port: int): self._target = (host, port) @@ -284,6 +289,14 @@ def __init__(self, host: str, port: int): self.port = self._listener.getsockname()[1] self._up = True self._stalled = False + # A predicate over one whole request (head and body): matching + # requests are held open and never answered. + self._stall_if = None + # (predicate, seconds): the first matching request reaches the server + # only that much later; its answer is relayed if anyone still listens. + self._slow_once = None + # time.monotonic() of every request stall_requests() held. + self.stalled: list[float] = [] self._lock = threading.Lock() self._sockets: set[socket.socket] = set() threading.Thread(target=self._accept, daemon=True).start() @@ -301,6 +314,10 @@ def _accept(self): if not self._up: client.close() continue + if self._stall_if is not None or self._slow_once is not None: + threading.Thread(target=self._look_then_route, + args=(client,), daemon=True).start() + continue try: upstream = socket.create_connection(self._target) except OSError: @@ -326,6 +343,71 @@ def _pump(source, sink): except OSError: pass + def _look_then_route(self, client): + """Read one HTTP request and route it: a request stall_requests() + picks is never answered, the first request slow_once() picks is + forwarded late, and anything else goes straight through.""" + request = b"" + continued = False + try: + client.settimeout(2.0) + while True: + head, found, body = request.partition(b"\r\n\r\n") + if found: + length = re.search(rb"(?i)content-length:\s*(\d+)", head) + if length is None or len(body) >= int(length.group(1)): + break + # libcurl holds a body over 1 KiB back until the server + # says 100 Continue, or for a second; answer for it, so + # routing a large statement does not add that second. + if not continued and re.search( + rb"(?i)\r\nexpect:\s*100-continue", head): + client.sendall(b"HTTP/1.1 100 Continue\r\n\r\n") + continued = True + chunk = client.recv(65536) + if not chunk: + break + request += chunk + client.settimeout(None) + except OSError: + client.close() + return + if continued: + # The server must not answer 100 Continue a second time. + head, _, body = request.partition(b"\r\n\r\n") + request = (re.sub(rb"(?i)\r\nexpect:[^\r\n]*", b"", head) + + b"\r\n\r\n" + body) + stall_if = self._stall_if + if stall_if is not None and stall_if(request): + with self._lock: + self.stalled.append(time.monotonic()) + self._sockets.add(client) # held open, never answered + return + slow = self._slow_once + if slow is not None and slow[0](request): + self._slow_once = None + time.sleep(slow[1]) + try: + upstream = socket.create_connection(self._target) + upstream.sendall(request) + except OSError: + client.close() + return + with self._lock: + self._sockets |= {client, upstream} + for source, sink in ((client, upstream), (upstream, client)): + threading.Thread(target=self._pump, args=(source, sink), + daemon=True).start() + + def stall_requests(self, predicate): + """Hold every new request `predicate(request_bytes)` picks open and + never answer it; the rest go through.""" + self._stall_if = predicate + + def slow_once(self, predicate, seconds: float): + """Forward the first request `predicate` picks `seconds` late.""" + self._slow_once = (predicate, seconds) + def cut(self): self._up = False with self._lock: @@ -346,6 +428,8 @@ def stall(self): def restore(self): self._up = True self._stalled = False + self._stall_if = None + self._slow_once = None def close(self): self.cut() @@ -961,6 +1045,23 @@ def _lease_row_live(client, prefix) -> bool: f"FROM {table} WHERE term = (SELECT max(term) FROM {table})")[0][0] == 1 +def _sample_lease(service, client, prefix, seconds, *, origin=None, + every=0.1): + """(t, lease_state, row live) every `every` s for `seconds`, t measured + from `origin` (time.monotonic(); the first sample by default). The state + is read before the row, so a sample that says "held" over a dead row + means the service called the lease held after the row had expired.""" + log = [] + origin = time.monotonic() if origin is None else origin + end = time.monotonic() + seconds + while time.monotonic() < end: + state = service.snapshot()["lease_state"] + log.append((round(time.monotonic() - origin, 2), state, + _lease_row_live(client, prefix))) + time.sleep(every) + return log + + def _held_but_dead(log): return [sample for sample in log if sample[1] == "held" and not sample[2]] @@ -1036,6 +1137,234 @@ def test_passes_over_committed_packs_do_not_hold_off_the_renewal( assert after["lease_renewals"] - before["lease_renewals"] >= 3, after +def test_a_stalled_renewal_gives_up_while_the_lease_row_is_still_live( + fake_s3, tmp_path): + """One renewal is three ClickHouse requests, and each was bounded only by + the client's request timeout -- 60 s by default, against a 15 s TTL -- + while the lease thread held the lease lock. A ClickHouse that accepted + the renewal's connection and never answered let the row expire with the + service still reporting the lease held, so a rival could take the + catalog before any error surfaced. Every request made under the lease is + now bounded by the lease deadline -- when the claim that stamped the row + was sent, plus the TTL, less the skew and a margin -- so the stalled + renewal fails, and the writer quarantines, while its row still keeps + rivals out.""" + spool_root = tmp_path / "spool" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (client, catalog): + config = _storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + reconcile_on_start=False, lease_ttl_s=3.0, publish_timeout_s=1, + # Longer than the TTL, so only the lease deadline can end the + # stalled request in time. + clickhouse_request_timeout_s=20.0) + service = _service(config, spool_root) + service.start() + try: + assert service.snapshot()["lease_state"] == "held" + stalled_at = time.monotonic() + switch.stall() + # Past the row's whole TTL, so the row has expired by the end. + log = _sample_lease(service, client, catalog.table_prefix, 4.0, + origin=stalled_at) + assert not _held_but_dead(log), log + quarantined = [t for t, state, _ in log if state == "quarantined"] + assert quarantined and quarantined[0] < 3.0, log + snapshot = service.snapshot() + assert "lease renewal failed" in snapshot["last_error"], snapshot + assert "Timeout" in snapshot["last_error"], snapshot + assert snapshot["failed"] is False, snapshot + + # The quarantine is the recoverable kind: the lease comes back. + switch.restore() + _wait_for(lambda: service.snapshot()["lease_state"] == "held", + timeout_s=10.0) + service.rethrow_if_failed() + finally: + switch.close() # releases the stalled connections + service.stop() + + +def _catalog_insert_but_the_lease(request: bytes) -> bool: + body = request.partition(b"\r\n\r\n")[2] + return body.startswith(b"INSERT") and b"_publisher_lease` (term" not in body + + +def test_a_stall_inside_the_index_pass_gives_up_while_the_lease_row_is_live( + fake_s3, tmp_path): + """The index pass holds the lease lock across its catalog requests -- the + version claim, the descriptor INSERTs, the publish and its read-backs -- + and those were bounded only by the client's request timeout. One that + stalled kept the lease thread from renewing: the row expired while the + snapshot still said "held", until the 20 s request timeout. The lease + deadline now bounds every request sent under the lease, not only the + lease's own, so the stalled INSERT fails, and the lease quarantines, + while the row is still live.""" + spool_root = tmp_path / "spool" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (client, catalog): + config = _storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + reconcile_on_start=False, lease_ttl_s=3.0, publish_timeout_s=1, + clickhouse_request_timeout_s=20.0) + service = _service(config, spool_root) + service.start() + try: + # Every catalog INSERT but the lease's own stalls, so the lease + # thread alone could keep the row alive -- if it got the lock. + switch.stall_requests(_catalog_insert_but_the_lease) + tensors = _stage(spool_root, range(2)) + _wait_for(lambda: switch.stalled, timeout_s=10.0) + log = _sample_lease(service, client, catalog.table_prefix, 8.0, + origin=switch.stalled[0]) + assert not _held_but_dead(log), log + quarantined = [t for t, state, _ in log if state == "quarantined"] + assert quarantined and quarantined[0] < 3.0, log + assert service.snapshot()["failed"] is False + + switch.restore() + service.flush(30.0) + service.rethrow_if_failed() + finally: + switch.close() + service.stop() + + captures = _read_all(_storage_config(fake_s3, catalog.table_prefix)) + assert sorted(captures) == sorted(tensors) + + +def _lease_head_read(request: bytes) -> bool: + return b"SELECT term, toString(lease_id)" in request + + +def test_start_survives_a_first_lease_read_slower_than_its_bound( + fake_s3, tmp_path): + """A claim made without a lease has min(clickhouse_request_timeout_s, + lease_ttl_s / 3) per request, and a cold server's first read can take + longer. start() failed outright when its claim timed out; it now retries + one that did, as it retries one another holder refused, until + start_lease_wait_s runs out. A head read that timed out wrote nothing, + so it does not quarantine the writer and the retry need not wait.""" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + knobs = dict(reconcile_on_start=False, lease_ttl_s=3.0, + publish_timeout_s=1) + # The schema first, directly: then the service's own claim is the + # first lease read through the switch. + warm = _service(_storage_config(fake_s3, catalog.table_prefix, + **knobs), tmp_path / "warm") + warm.start() + warm.stop() + + switch.slow_once(_lease_head_read, 1.5) # past the 1 s claim bound + service = _service(_storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + **knobs), tmp_path / "spool") + started = time.monotonic() + service.start() + try: + elapsed = time.monotonic() - started + snapshot = service.snapshot() + assert snapshot["lease_state"] == "held", snapshot + # Retried at once, without waiting out a 3 s quarantine. + assert 1.0 <= elapsed < 2.5, elapsed + assert "Timeout" in snapshot["last_error"], snapshot + finally: + service.stop() + switch.close() + + +def test_lease_requests_that_keep_timing_out_name_the_knobs_that_bound_them( + fake_s3, tmp_path): + """On a catalog too slow for its lease the service went round -- a claim + timed out, quarantined, was refused by its own late row, started over -- + and all the snapshot ever said was "curl: Timeout was reached". Once + three lease requests in a row time out, the snapshot names the bound + and the knobs that set it, until the lease renews again.""" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + config = _storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + reconcile_on_start=False, lease_ttl_s=3.0, publish_timeout_s=1, + clickhouse_request_timeout_s=20.0) + service = _service(config, tmp_path / "spool") + service.start() + try: + snapshot = service.snapshot() + assert snapshot["lease_timeouts"] == 0, snapshot + assert snapshot["lease_timeout_error"] == "", snapshot + + # The renewal times out at the lease deadline, then every claim + # at its own bound. + switch.stall() + _wait_for(lambda: service.snapshot()["lease_timeout_error"], + timeout_s=15.0) + snapshot = service.snapshot() + assert snapshot["lease_timeouts"] >= 3, snapshot + assert snapshot["failed"] is False, snapshot + for text in (snapshot["lease_timeout_error"], + snapshot["last_error"]): + for knob in ("lease_ttl_s", "clickhouse_request_timeout_s", + "lease_ttl_s / 3"): + assert knob in text, snapshot + + switch.restore() + _wait_for(lambda: service.snapshot()["lease_timeout_error"] == "", + timeout_s=15.0) + snapshot = service.snapshot() + assert snapshot["lease_state"] == "held", snapshot + assert snapshot["lease_timeouts"] == 0, snapshot + service.rethrow_if_failed() + finally: + switch.close() + service.stop() + + +def test_the_lease_statements_carry_a_server_side_cap(fake_s3, tmp_path): + """The claim INSERT went out with no max_execution_time, unlike every + fenced publish statement. A request the client gave up on could still + land its claim row later -- after the quarantine that was meant to + outlive it had ended. The cap makes the server abandon the INSERT no + later than the client does: the time left before the request's + deadline, rounded down, and lock_acquire_timeout the same.""" + with _catalog() as (client, catalog): + # The production knobs: a 15 s TTL. + config = _storage_config(fake_s3, catalog.table_prefix, + reconcile_on_start=False, holder="cap-test") + service = _service(config, tmp_path / "spool") + service.start() + service.stop() # the release tombstone is a lease INSERT too + + rows = [] + for _ in range(25): + client.execute("SYSTEM FLUSH LOGS") + rows = client.execute( + "SELECT query, Settings['max_execution_time'], " + "Settings['timeout_overflow_mode'], " + "Settings['lock_acquire_timeout'] FROM system.query_log " + "WHERE type = 'QueryFinish' AND query LIKE 'INSERT%' " + f"AND query LIKE '%{catalog.table_prefix}_publisher_lease%'") + ours = [query for query, *_ in rows if "'cap-test'" in query] + if len(ours) >= 2: + break + time.sleep(0.2) + # The service's claim and its tombstone, beside the schema check's. + assert len(ours) == 2, rows + for query, cap, overflow, lock in rows: + if "now_ns + toUInt64" in query: + # A claim with no lease held: min(clickhouse_request_timeout_s, + # lease_ttl_s / 3) = 5 s, less the microseconds since. + assert cap == "4", (query, cap) + else: + # A tombstone, under the lease: what is left of 15 s less + # the 0.1 s margin since the claim was sent. + assert cap in ("13", "14"), (query, cap) + assert lock == cap, (query, lock) + # The log lists only settings that differ from the default, and + # throw is the default; break would insert what had been read. + assert overflow in ("", "throw"), (query, overflow) + + def _latch_lines(err: str) -> list[str]: return [line for line in err.splitlines() if "indexing stopped" in line] diff --git a/tests/test_native_capture_storage_wiring.py b/tests/test_native_capture_storage_wiring.py index 3e38cd58c..21cead936 100644 --- a/tests/test_native_capture_storage_wiring.py +++ b/tests/test_native_capture_storage_wiring.py @@ -690,6 +690,44 @@ def test_a_lease_that_outlasts_the_fence_is_accepted(ttl, publish, skew): assert config.lease_ttl_s == ttl +@pytest.mark.parametrize("ttl, publish, skew", [ + (30.0, 5.0, 15.0), # the skew spends the renewal's whole half + (15.0, 5.0, 7.3), # 100 ms left for a renewal + (3.0, 1.0, 1.25), # 150 ms, at the live suites' TTL + (3.0, 1.0, 1.21), # 190 ms: just under the 200 ms floor +]) +def test_the_skew_must_leave_a_renewal_time_to_finish(ttl, publish, skew): + # Each clears the fence margin, but a renewal starts up to lease_ttl_s/2 + # after the claim that stamped the row was sent, and has to be answered + # by the lease deadline, lease_ttl_s less the skew and a 0.1 s margin + # after that send. The native service refuses these too. + with pytest.raises(ValueError, match="clock_skew_s") as refusal: + _storage_config(lease_ttl_s=ttl, publish_timeout_s=publish, + clock_skew_s=skew) + assert "lease_ttl_s" in str(refusal.value) + + +@pytest.mark.parametrize("ttl, publish, skew", [ + (15.0, 5.0, 0.0), # the defaults + (15.0, 5.0, 7.2), # exactly the 200 ms floor + (15.0, 5.0, 5.0), # 2.4 s, where (TTL / 3 - skew) / 4 leaves 0 + (3.0, 1.0, 1.2), # the floor at a 3 s TTL + (7.0, 5.0, 1.5), +]) +def test_a_skew_that_leaves_a_renewal_its_time_is_accepted(ttl, publish, skew): + config = _storage_config(lease_ttl_s=ttl, publish_timeout_s=publish, + clock_skew_s=skew) + assert config.clock_skew_s == skew + + +def test_the_request_timeout_does_not_bound_the_lease(): + # Requests under the lease are bounded by the lease deadline as well, so + # a generic request timeout longer than the TTL is not refused. + config = _storage_config(lease_ttl_s=3.0, publish_timeout_s=1, + clickhouse_request_timeout_s=120.0) + assert config.clickhouse_request_timeout_s == 120.0 + + @pytest.mark.parametrize("publish", [1.5, 0.5, 4.999]) def test_the_publish_timeout_is_whole_seconds(publish): # The native writer sends it as max_execution_time in whole seconds; a diff --git a/tests/test_native_lease_request_bound.py b/tests/test_native_lease_request_bound.py new file mode 100644 index 000000000..a4a5fac8c --- /dev/null +++ b/tests/test_native_lease_request_bound.py @@ -0,0 +1,389 @@ +"""The publisher lease's requests run under a deadline of their own. + +A lease renewal is three ClickHouse requests (head read, claim INSERT, +read-back), and each was bounded only by the catalog client's generic +request timeout -- 60 s by default, against a 15 s lease TTL. A server that +accepted a renewal and never answered let the row expire before any error +surfaced, and a claim INSERT the client gave up on carried no server-side +cap, so the server could still land it afterwards, outliving the quarantine +meant to cover it. + +While a lease is held, its requests now share the lease deadline: when the +claim that stamped the row was sent, plus the TTL, less the clock skew and a +0.1 s margin. Without one, each request of a claim is bounded by +min(request timeout, TTL / 3). The lease INSERTs carry the time left as +max_execution_time and lock_acquire_timeout, and cap a quorum wait by it. + +These drive the native coordinator (``native/build/conformance_catalog``) +against a scripted HTTP server standing in for ClickHouse, so the request +bound and the settings each lease statement carries are pinned on the CPU +gate. The same behaviour against a real server, through the storage +service, is in tests/test_native_capture_storage_live.py. +""" + +from __future__ import annotations + +import json +import os +import re +import subprocess +import threading +import time +import uuid +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer +from pathlib import Path +from urllib.parse import parse_qs, urlsplit + +import pytest + +REPO = Path(__file__).resolve().parents[1] +BUILD = REPO / "native" / "build" +DRIVER = BUILD / "conformance_catalog" +STORE_BUILT = bool(sorted(BUILD.glob("_dmi_native_store*.so"))) + +pytestmark = [ + pytest.mark.cpu, + pytest.mark.skipif( + not DRIVER.exists(), + reason="native/build/conformance_catalog is not built; run " + "`make -C native build/conformance_catalog`", + ), +] + +HEAD = "SELECT term, toString(lease_id)" +READ_BACK = "SELECT toString(lease_id), acquired_at_ns" + + +class _FakeClickHouse: + """Answers the lease protocol's statements as an empty catalog would, + records every request, and can stall a statement: accept it and never + answer until the test ends.""" + + def __init__(self): + self.requests: list[tuple[dict[str, str], str]] = [] + self.head_rows = "" # the head read's TSV answer; empty catalog + self.stall: str | None = None # a statement prefix to never answer + # (statement prefix, seconds): answer the first such statement late. + self.delay: tuple[str, float] | None = None + # (statement prefix, seconds): answer every such statement that late, + # with a 503 -- a failure the client retries for a read. + self.unavailable: tuple[str, float] | None = None + self._released = threading.Event() + self._claimed = "" + fake = self + + class Handler(BaseHTTPRequestHandler): + def do_POST(self): # noqa: N802 -- the http.server hook name + body = self.rfile.read( + int(self.headers["Content-Length"])).decode() + settings = {key: values[-1] for key, values in + parse_qs(urlsplit(self.path).query).items()} + fake.requests.append((settings, body)) + if fake.stall is not None and body.startswith(fake.stall): + fake._released.wait(30) + return + if fake.delay is not None and body.startswith(fake.delay[0]): + seconds = fake.delay[1] + fake.delay = None + time.sleep(seconds) + unavailable = fake.unavailable + if unavailable is not None and body.startswith(unavailable[0]): + time.sleep(unavailable[1]) + self.send_response(503) + self.send_header("Content-Length", "0") + self.end_headers() + return + if body.startswith("INSERT"): + fake._claimed = re.search( + r"toUUID\('([^']+)'\)", body).group(1) + answer = "" + elif body.startswith(HEAD): + answer = fake.head_rows + elif body.startswith(READ_BACK): + answer = f"{fake._claimed}\t1\t2\n" + else: + answer = "" + payload = answer.encode() + self.send_response(200) + self.send_header("Content-Length", str(len(payload))) + self.end_headers() + self.wfile.write(payload) + + def log_message(self, *args): + pass + + self._server = ThreadingHTTPServer(("127.0.0.1", 0), Handler) + self._server.daemon_threads = True + self.port = self._server.server_address[1] + threading.Thread(target=self._server.serve_forever, + daemon=True).start() + + def inserts(self) -> list[dict[str, str]]: + return [settings for settings, body in self.requests + if body.startswith("INSERT")] + + def close(self): + self._released.set() + self._server.shutdown() + self._server.server_close() + + +class _Driver: + def __init__(self, port: int): + env = dict(os.environ, DMI_CLICKHOUSE_HOST="127.0.0.1", + DMI_CLICKHOUSE_HTTP_PORT=str(port)) + self.proc = subprocess.Popen( + [str(DRIVER)], stdin=subprocess.PIPE, stdout=subprocess.PIPE, + text=True, bufsize=1, env=env) + + def call(self, **fields) -> dict: + self.proc.stdin.write(json.dumps(fields) + "\n") + self.proc.stdin.flush() + return json.loads(self.proc.stdout.readline()) + + def open(self, **overrides) -> dict: + fields = {"op": "open", "database": "default", + "table_prefix": "dmi_lease_bound", + "lease_ttl_ns": 15_000_000_000, + "publish_timeout_ns": 5_000_000_000, "clock_skew_ns": 0, + "allocation_attempts": 3, **overrides} + return self.call(**fields) + + def close(self): + self.proc.kill() + self.proc.wait(timeout=30) + + +@pytest.fixture +def fake(): + server = _FakeClickHouse() + yield server + server.close() + + +@pytest.fixture +def driver(fake): + process = _Driver(fake.port) + yield process + process.close() + + +@pytest.mark.parametrize("ttl_ns, publish_ns", [ + (30_000_000_000, 5_000_000_000), + (15_000_000_000, 5_000_000_000), # the service default + (3_000_000_000, 1_000_000_000), + (1_200_000_000, 1_000_000_000), +]) +def test_the_lease_inserts_carry_the_time_left_as_a_server_cap( + fake, driver, ttl_ns, publish_ns): + """A claim the client gave up on must not land afterwards: the server + abandons the INSERT at max_execution_time, and waits for a table lock no + longer (lock_acquire_timeout), never later than the client's own + deadline. A claim with no lease held has min(request timeout, TTL / 3); + the tombstone, sent under the lease, what is left of the TTL less the + 0.1 s margin. Whole seconds rounded down, a fraction only under one.""" + assert driver.open(lease_ttl_ns=ttl_ns, publish_timeout_ns=publish_ns)["ok"] + claimed = driver.call(op="claim", holder="h", lease_id=str(uuid.uuid4())) + assert claimed["ok"], claimed + assert driver.call(op="release")["ok"] + + claim, tombstone = fake.inserts() + claim_bound = min(60.0, ttl_ns / 3e9) + lease_left = ttl_ns / 1e9 - 0.1 + for settings, bound in ((claim, claim_bound), (tombstone, lease_left)): + cap = float(settings["max_execution_time"]) + assert 0 < cap < bound, settings + # Rounded down to whole seconds from one up: 9.99 s left sends "9". + assert cap >= bound - 1 if bound > 1 else cap > bound - 0.05, settings + assert settings["lock_acquire_timeout"] == \ + settings["max_execution_time"], settings + # break would insert whatever had been read by then. + assert settings.get("timeout_overflow_mode") == "throw", settings + assert "insert_quorum" not in settings, settings + assert settings["max_execution_time"] != "0", settings # no limit + + +def test_a_quorum_lease_insert_waits_no_longer_than_its_deadline( + fake, driver): + """max_execution_time does not cover the quorum wait, so the quorum + timeout is capped too, by the time left: past the client's deadline + nobody is listening. publish_timeout still caps it where that is less.""" + assert driver.open(lease_ttl_ns=12_000_000_000, + publish_timeout_ns=5_000_000_000, + clock_skew_ns=1_000_000, insert_quorum=2)["ok"] + assert driver.call(op="claim", holder="h", + lease_id=str(uuid.uuid4()))["ok"] + assert driver.call(op="release")["ok"] + + claim, tombstone = fake.inserts() + # No lease yet: TTL / 3 = 4 s left, less than the 5 s publish timeout. + assert 3900 < int(claim["insert_quorum_timeout"]) < 4000, claim + assert claim["max_execution_time"] == "3", claim + assert claim["insert_quorum"] == "2", claim + # Under the lease, nearly 12 s are left: publish_timeout caps it. + assert tombstone["insert_quorum_timeout"] == "5000", tombstone + + +def _timed(call): + outcome = {} + + def _run(): + started = time.monotonic() + outcome["response"] = call() + outcome["elapsed"] = time.monotonic() - started + + waiter = threading.Thread(target=_run, daemon=True) + waiter.start() + waiter.join(timeout=10.0) + assert not waiter.is_alive(), "the stalled lease request was not bounded" + return outcome["response"], outcome["elapsed"] + + +@pytest.mark.parametrize("statement", [HEAD, "INSERT", READ_BACK]) +def test_a_claim_request_never_answered_fails_within_the_claim_bound( + fake, driver, statement): + """With no lease held, each request of a claim gives up after + min(request timeout, TTL / 3) -- 1 s at a 3 s TTL -- not after the + client's 60 s request timeout, and the error names the knobs.""" + assert driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + fake.stall = statement + response, elapsed = _timed(lambda: driver.call( + op="claim", holder="h", lease_id=str(uuid.uuid4()))) + assert not response["ok"], response + assert response["error"] == "ClickHouseError", response + assert "Timeout" in response["message"], response + for knob in ("clickhouse_request_timeout_s", "lease_ttl_s / 3"): + assert knob in response["message"], response + assert 0.9 < elapsed < 1.5, elapsed + + +def test_a_renewal_may_use_all_the_time_its_row_has_left(fake, driver): + """A fixed bound per request, small enough for several requests to fit + the renewal window (TTL / 12), would quarantine a healthy but slow + catalog. A renewal's requests share the lease deadline instead, so one + slow request may use the row's whole remaining life -- and a stalled one + still fails 0.1 s before the row expires.""" + assert driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + claimed_at = time.monotonic() + assert driver.call(op="claim", holder="h", + lease_id=str(uuid.uuid4()))["ok"] + fake.stall = HEAD + response, _ = _timed(lambda: driver.call(op="renew")) + elapsed = time.monotonic() - claimed_at + assert not response["ok"], response + assert "Timeout" in response["message"], response + for knob in ("lease_ttl_s", "clock_skew_s", "clickhouse_request_timeout_s"): + assert knob in response["message"], response + assert 2.5 < elapsed < 3.0, elapsed + + +def test_retries_stop_at_the_deadline(fake, driver): + """A read the server answers with a 503 is retried, up to three attempts + with a backoff between them, and each attempt had the whole request + timeout: a claim's head read could take three times its bound, and more. + Under a deadline no attempt, and no backoff, runs past it.""" + assert driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + # 0.4 s an attempt: the second ends at 0.9 s, and the 0.2 s backoff + # before a third would end past the 1 s claim bound. + fake.unavailable = (HEAD, 0.4) + response, elapsed = _timed(lambda: driver.call( + op="claim", holder="h", lease_id=str(uuid.uuid4()))) + assert not response["ok"], response + assert "503" in response["message"], response + assert "not retried" in response["message"], response + assert "lease_ttl_s / 3" in response["message"], response + assert elapsed < 1.05, elapsed + heads = [body for _, body in fake.requests if body.startswith(HEAD)] + assert len(heads) == 2, heads + + +@pytest.mark.parametrize("statement, quarantined", [ + (HEAD, False), ("INSERT", True), (READ_BACK, True), +]) +def test_a_claim_quarantines_only_once_its_insert_may_have_landed( + fake, driver, statement, quarantined): + """acquire() quarantined the writer for a TTL on any ClickHouse error. A + claim whose head read failed has sent no INSERT, so no row of it can + land and there is nothing to wait out -- a claim that timed out at start + could be retried at once instead of failing, or waiting a TTL. One whose + INSERT went out has an unknown outcome and still quarantines. + (Deliberately unlike the Python oracle, which quarantines on any + error.)""" + assert driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + fake.stall = statement + response, _ = _timed(lambda: driver.call(op="acquire", holder="h")) + assert not response["ok"], response + assert "Timeout" in response["message"], response + assert driver.call(op="quarantined")["quarantined"] is quarantined + + +def test_a_slow_but_healthy_head_read_does_not_fail_the_claim(fake, driver): + """A head read with select_sequential_consistency on a loaded catalog + can take seconds, which a fixed TTL / 12 per request -- 1.25 s at the + service defaults -- would fail. A claim's request has min(request + timeout, TTL / 3) = 5 s.""" + assert driver.open()["ok"] + fake.delay = (HEAD, 2.0) + claimed = driver.call(op="claim", holder="h", lease_id=str(uuid.uuid4())) + assert claimed["ok"], claimed + + +# --- the storage service's configuration -------------------------------------- + + +def _service_config(tmp_path, **overrides): + config = { + "s3_endpoint": "http://127.0.0.1:1", "s3_bucket": "bucket", + "s3_access_key": "AKIA-test", "s3_secret_key": "secret-test", + "s3_allow_insecure_http": True, "store_id": "s3", + "clickhouse_host": "127.0.0.1", "clickhouse_port": 1, + "database": "default", "table_prefix": "dmi_lease_bound", + "spool_root": str(tmp_path / "spool"), "holder": "h", + "lease_ttl_ns": 3_000_000_000, "publish_timeout_ns": 1_000_000_000, + "clock_skew_ns": 0, + } + config.update(overrides) + return config + + +@pytest.mark.skipif(not STORE_BUILT, + reason="the native store module is not built") +@pytest.mark.parametrize("ttl_ns, skew_ns", [ + (3_000_000_000, 1_250_000_000), # 150 ms left for a renewal + (3_000_000_000, 1_210_000_000), # 190 ms: under the 200 ms floor + (30_000_000_000, 15_000_000_000), # nothing left at all +]) +def test_the_service_refuses_a_skew_that_leaves_a_renewal_no_time( + tmp_path, ttl_ns, skew_ns): + # A renewal starts up to lease_ttl / 2 after the claim that stamped the + # row was sent, and must be answered by the lease deadline, lease_ttl + # less the skew and the 0.1 s margin after that send. + from dmi.storage.native_capture import _load_native_store_extension + + module = _load_native_store_extension() + with pytest.raises(ValueError, match="clock_skew_ns") as refusal: + module.StorageService(_service_config( + tmp_path, lease_ttl_ns=ttl_ns, clock_skew_ns=skew_ns)) + assert "lease_ttl_ns" in str(refusal.value) + + +@pytest.mark.skipif(not STORE_BUILT, + reason="the native store module is not built") +@pytest.mark.parametrize("ttl_ns, skew_ns, request_s", [ + (15_000_000_000, 0, 60.0), # the defaults + (3_000_000_000, 1_200_000_000, 60.0), # exactly the floor + (15_000_000_000, 5_000_000_000, 60.0), # (TTL / 3 - skew) / 4 is 0 + (3_000_000_000, 0, 120.0), # a request timeout past the TTL +]) +def test_the_service_accepts_a_renewal_that_fits(tmp_path, ttl_ns, skew_ns, + request_s): + from dmi.storage.native_capture import _load_native_store_extension + + module = _load_native_store_extension() + module.StorageService(_service_config( + tmp_path, lease_ttl_ns=ttl_ns, clock_skew_ns=skew_ns, + clickhouse_request_timeout_s=request_s)) diff --git a/tests/tools/verify_replicated_quorum.py b/tests/tools/verify_replicated_quorum.py index 8bae5aa98..2d9730060 100644 --- a/tests/tools/verify_replicated_quorum.py +++ b/tests/tools/verify_replicated_quorum.py @@ -53,7 +53,12 @@ (`CatalogVersionAllocationError`). 6. An unsatisfiable quorum is refused immediately (Code 285, TOO_FEW_LIVE_REPLICAS) rather than parking for ClickHouse's 600-second - default, because `insert_quorum_timeout` is bounded to `publish_timeout_ns`. + default, because `insert_quorum_timeout` is bounded to `publish_timeout_ns` + -- and, on the publisher lease's own INSERTs, also to the time left before + the request's deadline (native/csrc/catalog/lease_coordinator.h): the lease + deadline while a lease is held, min(request timeout, TTL / 3) for a claim + made without one. At the 30 s TTL the native leg runs with, that is 10 s or + more, so the lease's timeout is `publish_timeout_ns` too. """ from __future__ import annotations @@ -399,6 +404,9 @@ def _main_native(client, prefix: str, control_prefix: str, driver_path) -> None: assert quorum == "2", f"{fragment}: insert_quorum was {quorum!r}" assert parallel == "0", ( f"{fragment}: insert_quorum_parallel was {parallel!r}") + # publish_timeout_ns for every table. The lease's own INSERTs + # are capped by the time left before their deadline as well, + # which at the 30 s TTL (DEFAULTS) is never below 10 s. assert timeout_ms == "5000", ( f"{fragment}: insert_quorum_timeout was {timeout_ms!r}") print("PASS server recorded insert_quorum=2, parallel=0 and the " From e5e46d2acadc92e4bfab7a078fb11ad1ba4380a1 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Sun, 27 Sep 2026 22:44:14 -0400 Subject: [PATCH 03/13] Read an index pass's packs from the object store outside the lease lock The index pass held the lease lock across the whole of indexer_.index(), its object-store reads included: each pending pack's footer and descriptor rows come from ranged GETs, bounded only by the S3 client's read timeout, 120 s by default. The lease deadline bounds catalog requests, not those, so a GET that stalled kept the lease thread from renewing for as long, and the row expired while the snapshot said "held". NativeIndexer::index() is now plan() -- deduplication and the replay guard, a catalog read -- then read(), the object store only, then commit(): the version, the descriptor writes, the publish and the inventory. The storage service holds the lease lock (a LeaseScope) for plan() and for commit() and reads the packs without it, so the lease keeps renewing through a stalled read. index() still runs the three in one call, for the conformance driver. Two things follow from letting go of the lock mid-pass: - commit() may run under another lease than plan() did: the lease can be lost and taken afresh while the pass reads, and another publisher can hold the catalog meanwhile and index the same packs, which its reconcile finds uploaded and uncommitted. The plan records the lease_id its replay guard was read under, and commit() reads the guard again when the lease is not that one, dropping what has been committed since. Trusting the old read published those packs a second time, at a higher version. - a long commit (many descriptor chunks) must not run the lease down while it holds the lock. IndexerConfig::keep_lease is called before the version claim and before each descriptor chunk, and the service renews there when the renewal is due. Not before the inventory commit: that follows a publish, which has just renewed, and a renewal failing there would leave the packs it made visible unrecorded. Tests first, in tests/test_native_capture_storage_live.py. The TCP switch can now stand in front of the fake S3 too. With every ranged GET stalled (for a new pack only the indexer's footer reads are ranged), the lease must stay held and live for 6 s, two TTLs, renewing at least three times. On the previous commit the snapshot said "held" over a dead row from 2.92 s into the stall, and main failed it too. The pack indexes once the read fails. A conformance-driver flag, rival_indexes_before_commit, releases the lease between read() and commit(), lets a second writer take it and index the same packs, and takes a fresh lease: with the re-read disabled the pass published both packs again (indexed_packs 2); with it both are skipped, and the catalog holds each descriptor once, at the rival's version. At this commit the CPU lease tests and the storage and lease live suites pass. --- native/csrc/catalog/conformance_catalog.cpp | 24 +++- native/csrc/catalog/indexer.cpp | 113 +++++++++++++----- native/csrc/catalog/indexer.h | 35 ++++++ native/csrc/catalog/storage_service.cpp | 41 +++++-- native/csrc/catalog/storage_service.h | 5 +- tests/test_native_capture_storage_live.py | 120 +++++++++++++++++++- 6 files changed, 297 insertions(+), 41 deletions(-) diff --git a/native/csrc/catalog/conformance_catalog.cpp b/native/csrc/catalog/conformance_catalog.cpp index d82ee5a5a..83ec992f3 100644 --- a/native/csrc/catalog/conformance_catalog.cpp +++ b/native/csrc/catalog/conformance_catalog.cpp @@ -312,6 +312,7 @@ std::string rows_to_json(const std::vector& rows) { struct Session { std::shared_ptr client; std::unique_ptr writer; + dmi_catalog::WriterConfig writer_config; std::string database; std::string table_prefix; }; @@ -380,6 +381,7 @@ Session make_session(const std::string& line) { session.client = std::make_shared(connection); session.writer = std::make_unique(session.client, config); + session.writer_config = config; session.database = config.database; session.table_prefix = config.table_prefix; return session; @@ -1042,9 +1044,27 @@ std::string respond(const std::string& line, Session* session) { {{"version", version + 1}}); }; } - const dmi_catalog::IndexResultData result = - dmi_catalog::NativeIndexer(&s3, &writer, index_config) + dmi_catalog::NativeIndexer indexer(&s3, &writer, index_config); + dmi_catalog::IndexPlan plan = indexer.plan(refs); + indexer.read(&plan); + if (jc::FindBool(line, "rival_indexes_before_commit")) { + // The window the storage service opens by reading packs without its + // lease lock: the lease is lost while the pass reads, another + // publisher holds the catalog meanwhile and indexes the same packs, + // and a fresh lease is taken before the pass commits. + const PublisherLease* held = writer.held_lease(); + const std::string holder = held != nullptr ? held->holder : "indexer"; + writer.release_lease(); + { + CatalogWriter rival(session->client, session->writer_config); + rival.acquire_lease("rival"); + dmi_catalog::NativeIndexer(&s3, &rival, dmi_catalog::IndexerConfig{}) .index(refs); + rival.release_lease(); + } + writer.acquire_lease(holder); + } + const dmi_catalog::IndexResultData result = indexer.commit(&plan); out = ",\"result\":{\"requested_packs\":" + std::to_string(result.requested_packs) + ",\"skipped_packs\":" + std::to_string(result.skipped_packs) + diff --git a/native/csrc/catalog/indexer.cpp b/native/csrc/catalog/indexer.cpp index 9281ea00c..8e8888d10 100644 --- a/native/csrc/catalog/indexer.cpp +++ b/native/csrc/catalog/indexer.cpp @@ -2,8 +2,11 @@ #include #include +#include #include #include +#include +#include namespace dmi_catalog { @@ -19,10 +22,10 @@ uint64_t NowWallClockNs() { } std::vector PackIdentitiesFrom( - const std::vector& refs) { + const std::vector& refs) { std::vector out; - for (const PackRefData* ref : refs) { - out.emplace_back(ref->store_id, ref->pack_id); + for (const PackRefData& ref : refs) { + out.emplace_back(ref.store_id, ref.pack_id); } return out; } @@ -85,15 +88,14 @@ std::string ConflictMessage(const PackIdentity& identity) { // The six version-independent pack columns; commit_packs appends the // batch's index_version itself, the same convention as write_descriptors. -std::vector RenderPackRows( - const std::vector& refs) { +std::vector RenderPackRows(const std::vector& refs) { std::vector rows; - for (const PackRefData* ref : refs) { - rows.push_back(sql_uuid(ref->pack_id) + "," + sql_quote(ref->store_id) + - "," + sql_quote(ref->object_key) + "," + - std::to_string(ref->object_bytes) + "," + - sql_quote(ref->checksum) + "," + - std::to_string(ref->record_count)); + for (const PackRefData& ref : refs) { + rows.push_back(sql_uuid(ref.pack_id) + "," + sql_quote(ref.store_id) + + "," + sql_quote(ref.object_key) + "," + + std::to_string(ref.object_bytes) + "," + + sql_quote(ref.checksum) + "," + + std::to_string(ref.record_count)); } return rows; } @@ -126,7 +128,18 @@ uint64_t NativeIndexer::allocate_version() { } IndexResultData NativeIndexer::index(const std::vector& refs) { - IndexResultData result; + IndexPlan planned = plan(refs); + read(&planned); + return commit(&planned); +} + +void NativeIndexer::keep_lease() const { + if (config_.keep_lease) config_.keep_lease(); +} + +IndexPlan NativeIndexer::plan(const std::vector& refs) { + IndexPlan planned; + IndexResultData& result = planned.result; if (static_cast(refs.size()) > config_.max_packs) { throw CatalogError( CatalogError::Kind::kValue, @@ -197,6 +210,8 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { result.requested_packs = unique.size() + result.failures.size(); // The replay guard, and nothing else: visibility comes from publish. + const PublisherLease* held = writer_->held_lease(); + planned.planned_under = held != nullptr ? held->lease_id : ""; std::set committed; if (!unique.empty()) { std::vector identities; @@ -206,31 +221,32 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { committed = writer_->committed_pack_ids(identities); } - std::vector pending; - uint64_t estimated_bytes = 0; for (const PackRefData* ref : unique) { if (committed.count({ref->store_id, ref->pack_id})) continue; - pending.push_back(ref); + planned.pending.push_back(*ref); } - result.skipped_packs = unique.size() - pending.size(); + result.skipped_packs = unique.size() - planned.pending.size(); + return planned; +} - std::vector all_rows; +void NativeIndexer::read(IndexPlan* planned) { + planned->read = true; + IndexResultData& result = planned->result; // Successes are COLLECTED, never removed from the sequence being // walked: erasing from `pending` mid-walk shifts every later pack one // slot left while the walk carries on past the hole, so the pack behind // a failure is never read yet still published and committed as indexed // (committed and invisible, which no later pass can repair) and the last // pack is read twice. `valid_refs` in catalog.py, for the same reason. - std::vector indexed; - for (const PackRefData* ref : pending) { + for (const PackRefData& ref : planned->pending) { std::vector rows; try { - rows = read_pack_descriptor_rows(s3_, *ref); + rows = read_pack_descriptor_rows(s3_, ref); } catch (const CatalogError& e) { std::string message = e.what(); if (message.size() > 512) message.resize(512); result.failures.push_back( - {ref->pack_id, ref->object_key, "CatalogError", message}); + {ref.pack_id, ref.object_key, "CatalogError", message}); continue; } uint64_t pack_bytes = 0; @@ -243,6 +259,7 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { // inside, the handler for unreadable packs caught it and blamed the // pack that happened to cross the budget — then every pack behind it — // and returned a partial index reporting success. + const uint64_t estimated_bytes = planned->estimated_bytes; if (estimated_bytes + pack_bytes > config_.max_estimated_bytes) { throw CatalogError( CatalogError::Kind::kBatchTooLarge, @@ -250,15 +267,23 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { std::to_string(estimated_bytes + pack_bytes) + " > " + std::to_string(config_.max_estimated_bytes)); } - estimated_bytes += pack_bytes; - all_rows.insert(all_rows.end(), rows.begin(), rows.end()); - indexed.push_back(ref); + planned->estimated_bytes += pack_bytes; + planned->indexed.push_back(ref); + planned->rows.push_back(std::move(rows)); } +} - if (!all_rows.empty() || !indexed.empty()) { +IndexResultData NativeIndexer::commit(IndexPlan* planned) { + if (!planned->read) { + throw std::logic_error("NativeIndexer::commit before read"); + } + IndexResultData& result = planned->result; + std::vector& indexed = planned->indexed; + if (!indexed.empty()) { // Fail before the batch is written, not after it is wasted: a writer // without publishing authority discovers it last otherwise. - if (writer_->held_lease() == nullptr) { + const PublisherLease* held = writer_->held_lease(); + if (held == nullptr) { throw CatalogError( CatalogError::Kind::kLease, "the catalog writer holds no publisher lease, and only the " @@ -266,11 +291,42 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { "indexing. Refused before allocating a version and writing " "descriptors, neither of which this pass could have published."); } + if (held->lease_id != planned->planned_under) { + // The lease was lost and a fresh one taken while the packs were read, + // so the replay guard was read under another lease, and a publisher + // that held the catalog in between may have committed these packs. + // Read it again, under the lease that is to publish them. + const std::set committed = + writer_->committed_pack_ids(PackIdentitiesFrom(indexed)); + std::vector still; + std::vector> still_rows; + for (size_t i = 0; i < indexed.size(); ++i) { + if (committed.count({indexed[i].store_id, indexed[i].pack_id})) { + ++result.skipped_packs; + continue; + } + still.push_back(std::move(indexed[i])); + still_rows.push_back(std::move(planned->rows[i])); + } + indexed.swap(still); + planned->rows.swap(still_rows); + } + } + std::vector all_rows; + for (std::vector& rows : planned->rows) { + all_rows.insert(all_rows.end(), std::make_move_iterator(rows.begin()), + std::make_move_iterator(rows.end())); + } + planned->rows.clear(); + + if (!all_rows.empty() || !indexed.empty()) { + keep_lease(); uint64_t version = allocate_version(); uint64_t descriptor_inserts = 0; const auto write_batches = [&](uint64_t at_version) { for (size_t start = 0; start < all_rows.size(); start += config_.max_rows_per_insert) { + keep_lease(); std::vector chunk( all_rows.begin() + static_cast(start), all_rows.begin() + @@ -321,6 +377,7 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { // competitor published, so the head read on the first allocation // is stale at exactly the moment the cross-check matters. published_version_.reset(); + keep_lease(); version = allocate_version(); write_batches(version); continue; @@ -334,6 +391,8 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { "could not publish a catalog snapshot after " + std::to_string(config_.max_publish_attempts) + " attempts"); } + // No keep_lease() here: the publish has just renewed, and a renewal + // that failed now would leave the packs it made visible unrecorded. if (!indexed.empty()) { writer_->commit_packs(RenderPackRows(indexed), version); } @@ -343,7 +402,7 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { result.indexed_packs = indexed.size(); result.indexed_rows = all_rows.size(); result.failed_packs = result.failures.size(); - result.estimated_bytes = estimated_bytes; + result.estimated_bytes = planned->estimated_bytes; return result; } diff --git a/native/csrc/catalog/indexer.h b/native/csrc/catalog/indexer.h index bed56bd3a..4bff76965 100644 --- a/native/csrc/catalog/indexer.h +++ b/native/csrc/catalog/indexer.h @@ -33,6 +33,12 @@ struct IndexerConfig { // published head to move between an allocation and its publish, which // only something outside this call can do. Left empty, this is nothing. std::function after_allocate; + // Called before each catalog write commit() makes -- the version claim, + // each descriptor chunk, the inventory commit -- so that a long pass can + // renew its lease when that falls due, instead of running the lease down + // while its caller holds the lease lock. The publish renews on its own. + // What it throws propagates. Unset: nothing. + std::function keep_lease; }; struct IndexFailureData { @@ -53,15 +59,44 @@ struct IndexResultData { std::vector failures; }; +// One index() pass, split at its object-store reads so that a caller can +// hold the catalog's lease lock for the catalog phases only: plan() and +// commit() talk to the catalog, read() only to the object store. A read that +// stalls then cannot keep the lease from renewing. +struct IndexPlan { + IndexResultData result; // requested, skipped and failures so far + std::vector pending; // not yet committed, in read order + // The lease the replay guard was read under ("" for none). commit() reads + // the guard again if the lease has changed since: a pass that lost its + // lease while reading may find the packs committed by another publisher. + std::string planned_under; + bool read = false; + // Filled by read(): the packs read, each with its rendered rows. + std::vector indexed; + std::vector> rows; + uint64_t estimated_bytes = 0; +}; + class NativeIndexer { public: NativeIndexer(dmi_store::S3Client* s3, CatalogWriter* writer, IndexerConfig config); + // plan(), read() and commit() in one call. IndexResultData index(const std::vector& refs); + // Deduplicates refs and reads the replay guard (the catalog). + IndexPlan plan(const std::vector& refs); + // Reads each pending pack's descriptor rows (the object store only). + // Throws kBatchTooLarge past max_estimated_bytes. + void read(IndexPlan* plan); + // Allocates a version, writes the descriptors, publishes and commits the + // inventory (the catalog). Requires read(). + IndexResultData commit(IndexPlan* plan); + private: uint64_t allocate_version(); + void keep_lease() const; dmi_store::S3Client* s3_; CatalogWriter* writer_; diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index ae9f85e8a..ee800d01d 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -109,7 +109,11 @@ CaptureStorageService::CaptureStorageService(StorageServiceConfig config) s3_(config_.s3), clickhouse_(std::make_shared(config_.clickhouse)), writer_(clickhouse_, config_.writer), - indexer_(&s3_, &writer_, config_.indexer) { + indexer_(&s3_, &writer_, [this] { + IndexerConfig indexer = config_.indexer; + indexer.keep_lease = [this] { keep_lease_in_pass(); }; + return indexer; + }()) { if (config_.spool_root.empty()) { throw std::invalid_argument("storage service: spool_root is required"); } @@ -490,12 +494,21 @@ void CaptureStorageService::index_bounded(std::vector refs, work.pop_back(); IndexResultData result; try { - // Nothing here stamps a renewal: the schedule follows the lease itself - // (renew_lease_if_due), which only a claim that confirmed moves -- a - // pass that published nothing, over packs already committed, renewed - // nothing. + // The lease lock for the catalog phases only. Between them the pass + // reads its packs from the object store, where a stalled GET is bound + // only by the S3 client's own timeouts, and must not keep the lease + // thread from renewing meanwhile. Nothing here stamps a renewal: the + // schedule follows the lease itself (renew_lease_if_due), which only + // a claim that confirmed moves -- a pass that published nothing, over + // packs already committed, renewed nothing. + IndexPlan plan; + { + LeaseScope lease(this); + plan = indexer_.plan(batch); + } + indexer_.read(&plan); LeaseScope lease(this); - result = indexer_.index(batch); + result = indexer_.commit(&plan); } catch (const CatalogError& exc) { if (exc.kind() == CatalogError::Kind::kBatchTooLarge && batch.size() > 1) { const size_t middle = batch.size() / 2; @@ -697,7 +710,9 @@ void CaptureStorageService::renew_lease_if_due() { // TTL of that send, and has until the lease deadline to be answered: the // renewal window the constructor checks (lease_coordinator.h). A stretch // under the lease lock delays it, but every request in such a stretch is - // bounded by the same deadline. A failed renewal costs the lease at once: a refusal drops it in the coordinator, and any other + // bounded by the same deadline, and a pass renews through the indexer's + // keep_lease hook before each catalog write. A failed renewal costs the + // lease at once: a refusal drops it in the coordinator, and any other // error quarantines the writer (renew_for_publish). const uint64_t ttl = config_.writer.lease_ttl_ns; const uint64_t sent = writer_.lease_sent_ns(); @@ -709,6 +724,18 @@ void CaptureStorageService::renew_lease_if_due() { ++state_.lease_renewals; } +void CaptureStorageService::keep_lease_in_pass() { + try { + renew_lease_if_due(); + } catch (const CatalogError&) { + throw; // a refusal: the pass fails with the lease lost + } catch (const std::exception& exc) { + record_error(std::string("lease renewal failed: ") + exc.what()); + note_lease_failure(exc); + throw; + } +} + void CaptureStorageService::abandon_lease_if_expired() { const uint64_t deadline = writer_.lease_deadline_ns(); if (deadline == 0 || steady_ns() < deadline) return; diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index 06be119e6..93ac28dc6 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -46,7 +46,8 @@ // lock is held: so a catalog that stops answering fails the stretch, and the // lease quarantines, while its row still keeps rivals out. A lease whose // deadline passes unrenewed is abandoned, never reported held (LeaseScope). -// Claims made with no +// An index pass reads its packs from the object store without the lock, so +// a stalled read cannot hold the renewal off either. Claims made with no // lease are bounded by min(request timeout, lease_ttl / 3) per request; a // claim that times out at start() is retried until start_lease_wait_ns ends, // and lease requests that keep timing out say which knobs bound them @@ -229,6 +230,8 @@ class CaptureStorageService { void reconcile(); void keep_lease(); // the lease thread's body void renew_lease_if_due(); // requires lease_mutex_ + // The indexer's keep_lease hook: renew_lease_if_due() inside a pass. + void keep_lease_in_pass(); // requires lease_mutex_ // Gives up a held lease whose deadline has passed. Requires lease_mutex_. void abandon_lease_if_expired(); // A lease claim or renewal failed (call from its catch block): one that diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index c0f85773b..6d7ee53a6 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -276,10 +276,11 @@ def test_the_reference_reader_sees_the_same_captures(fake_s3, tmp_path): class _Switch: - """A TCP forwarder in front of ClickHouse's HTTP port that can be cut - (connections refused), stalled (connections accepted, never answered), - made to stall only the requests a predicate picks, or to hold the first - request a predicate picks back for a while. Every + """A TCP forwarder in front of an HTTP server -- ClickHouse's HTTP port, + or the fake S3 -- that can be cut (connections refused), stalled + (connections accepted, never answered), made to stall only the requests + a predicate picks, or to hold the first request a predicate picks back + for a while. Every native client opens one connection per request, so one request is one connection here.""" @@ -301,6 +302,15 @@ def __init__(self, host: str, port: int): self._sockets: set[socket.socket] = set() threading.Thread(target=self._accept, daemon=True).start() + @classmethod + def to_url(cls, url: str) -> "_Switch": + host, port = url.split("://", 1)[1].rstrip("/").rsplit(":", 1) + return cls(host, int(port)) + + @property + def url(self) -> str: + return f"http://127.0.0.1:{self.port}" + def _accept(self): while True: try: @@ -1233,6 +1243,108 @@ def test_a_stall_inside_the_index_pass_gives_up_while_the_lease_row_is_live( assert sorted(captures) == sorted(tensors) +def _ranged_get(request: bytes) -> bool: + head = request.partition(b"\r\n\r\n")[0].lower() + return head.startswith(b"get ") and b"\r\nrange:" in head + + +def test_a_stalled_object_store_read_does_not_hold_up_the_lease( + fake_s3, tmp_path): + """The index pass read each pack's footer from the object store with the + lease lock held, so a GET that stalled -- bounded only by the S3 read + timeout, 120 s by default -- kept the lease thread from renewing, and the + row expired while the snapshot said "held". The pass now takes the lock + only for its catalog requests and reads packs without it, so the lease + keeps renewing through a stalled read.""" + spool_root = tmp_path / "spool" + s3 = _Switch.to_url(fake_s3) + with _catalog() as (client, catalog): + config = _storage_config( + s3.url, catalog.table_prefix, reconcile_on_start=False, + lease_ttl_s=3.0, publish_timeout_s=1) + service = _service(config, spool_root) + service.start() + try: + # The uploader PUTs and HEADs a new pack; only the indexer's + # footer reads are ranged GETs. + s3.stall_requests(_ranged_get) + tensors = _stage(spool_root, range(2)) + _wait_for(lambda: s3.stalled, timeout_s=10.0) + renewals = service.snapshot()["lease_renewals"] + # Two TTLs: without renewals the row would be long dead. + log = _sample_lease(service, client, catalog.table_prefix, 6.0, + origin=s3.stalled[0]) + assert all(state == "held" and live + for _, state, live in log), log + assert service.snapshot()["lease_renewals"] >= renewals + 3 + + # Fail the stalled read: the pack stays owed and indexes after. + s3.cut() + s3.restore() + service.flush(30.0) + service.rethrow_if_failed() + finally: + s3.close() + service.stop() + + captures = _read_all(_storage_config(fake_s3, catalog.table_prefix)) + assert sorted(captures) == sorted(tensors) + + +def test_a_pass_whose_lease_changed_while_it_read_rereads_the_replay_guard( + fake_s3, tmp_path): + """Reading packs without the lease lock opens a window the whole-pass + lock did not have: the lease can be lost and taken afresh while the pass + reads, and another publisher can hold the catalog meanwhile and index + the same packs (its reconcile finds them uploaded and uncommitted). The + replay guard the pass read first no longer holds then, and a commit that + trusted it would publish the packs a second time, at a higher version. + The commit reads the guard again when the lease is not the one it was + read under.""" + from tests.test_native_catalog_lease_live import CatalogDriver, _open + + spool_root = tmp_path / "spool" + _stage(spool_root, range(4)) # two packs + store = _Driver(STORE_DRIVER) + try: + uploaded = store.call( + op="upload_pending", endpoint=fake_s3, bucket=BUCKET, + region=REGION, access=ACCESS, secret=SECRET, token=None, + insecure=True, connect_timeout=5, read_timeout=15, max_attempts=4, + store_id="s3", root=str(spool_root), spool_max_bytes=1 << 40, + limit=-1, max_workers=4, max_in_flight_bytes=1 << 30) + assert uploaded["ok"], uploaded + finally: + store.close() + refs = uploaded["refs"] + assert len(refs) == 2, refs + + with _catalog() as (client, catalog): + driver = CatalogDriver() + try: + _open(driver, catalog.table_prefix) + assert driver.call(op="ensure_schema")["ok"] + assert driver.call(op="acquire", holder="indexer")["ok"] + result = driver.call( + op="index", refs=refs, endpoint=fake_s3, bucket=BUCKET, + region=REGION, access=ACCESS, secret=SECRET, insecure=True, + rival_indexes_before_commit=True) + assert result["ok"], result + assert result["result"]["indexed_packs"] == 0, result + assert result["result"]["skipped_packs"] == 2, result + assert driver.call(op="release")["ok"] + finally: + driver.close() + + table = f"`{DATABASE}`.`{catalog.table_prefix}_capture_raw`" + # The rival's one publish, not a second copy of every descriptor. + assert client.execute( + f"SELECT count(), uniqExact(index_version) FROM {table}") == [ + (4, 1)] + captures = _read_all(_storage_config(fake_s3, catalog.table_prefix)) + assert len(captures) == 4 + + def _lease_head_read(request: bytes) -> bool: return b"SELECT term, toString(lease_id)" in request From 03ab69ce8b383a83160dfd615b3c0258cf633905 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Sun, 27 Sep 2026 22:46:55 -0400 Subject: [PATCH 04/13] Keep the service's own late claim rows out of the lease latch The caps on a lease INSERT cannot cover every late landing: ClickHouse checks max_execution_time only at points inside the pipeline, and starts its clock when the query reaches the server, so a claim held up in transit still lands after the client gave up and quarantined. That row then refuses the service's next claim once the quarantine ends. The refusal clock is reset only when a claim succeeds, so refusals by a rival that had since left, followed by refusals from the service's own late row, added up to 2 x TTL and latched "held by another publisher" -- naming the service's own holder. LeaseCoordinator now remembers the lease_ids of its recent claim INSERTs (sent, confirmed or not; each id once, so the renewals of one lease, which all claim the same id, cannot push an earlier claim out of the 16-entry history) and records whether a refusal came only from those rows; CatalogWriter::refused_by_own_claims() exposes it. The service restarts the refusal clock on such a refusal instead of counting it. That is sound: the late claim was only sent because its head read found no live rival, so any earlier rival's refusals ended there; the row expires one TTL after it landed; and while it refuses, the service's claims stop at the head read, so no further rows of its own appear. A contested head with any foreign claimant still counts. The conformance driver reports the attribution on a refusal as own_claims. Test first in tests/test_native_capture_storage_live.py: the TCP switch can now hold lease INSERTs back and deliver them late. A rival takes over during a cut and leaves 4 s into its refusals; the first service's next claim reaches the server 1.5 s late, after the 1 s bound on a claim made without a lease (lease_ttl_s / 3), and lands inside the quarantine. With the reset disabled the service latched against 'first-publisher' itself; now it takes the lease back. The attribution is pinned on the CPU gate in tests/test_native_lease_request_bound.py (own row: true; contested with a rival, or another coordinator: false), and so is the history: twenty renewals of one lease used to crowd out an earlier claim, which then read as a rival's (own_claims false). The cpu tier, and the storage, lease, chain, reader-parity and lease-bound suites live, pass. --- native/csrc/catalog/catalog_writer.cpp | 6 ++ native/csrc/catalog/catalog_writer.h | 3 + native/csrc/catalog/conformance_catalog.cpp | 9 +- native/csrc/catalog/lease_coordinator.cpp | 23 ++++- native/csrc/catalog/lease_coordinator.h | 14 +++ native/csrc/catalog/storage_service.cpp | 19 +++- native/csrc/catalog/storage_service.h | 5 +- tests/test_native_capture_storage_live.py | 97 +++++++++++++++++++-- tests/test_native_lease_request_bound.py | 56 ++++++++++++ 9 files changed, 221 insertions(+), 11 deletions(-) diff --git a/native/csrc/catalog/catalog_writer.cpp b/native/csrc/catalog/catalog_writer.cpp index b766d7148..425117aec 100644 --- a/native/csrc/catalog/catalog_writer.cpp +++ b/native/csrc/catalog/catalog_writer.cpp @@ -329,6 +329,12 @@ void CatalogWriter::abandon_lease() { if (leases_->lease() != nullptr) quarantine(); } +bool CatalogWriter::refused_by_own_claims() const { + require_owned_by_this_process(); + const std::lock_guard serial(serial_); + return leases_->refused_by_own_claims(); +} + void CatalogWriter::release_lease() { require_owned_by_this_process(); const std::lock_guard serial(serial_); diff --git a/native/csrc/catalog/catalog_writer.h b/native/csrc/catalog/catalog_writer.h index fb90fad5d..787c86d87 100644 --- a/native/csrc/catalog/catalog_writer.h +++ b/native/csrc/catalog/catalog_writer.h @@ -108,6 +108,9 @@ class CatalogWriter { // running, so it goes as an unknown outcome does: no tombstone, and // quarantined for a TTL. void abandon_lease(); + // Whether the last lease refusal came only from this writer's own earlier + // claim rows (LeaseCoordinator::refused_by_own_claims). + bool refused_by_own_claims() const; uint64_t allocate_version(); uint64_t max_version(const std::string& table, const std::string& column) const; diff --git a/native/csrc/catalog/conformance_catalog.cpp b/native/csrc/catalog/conformance_catalog.cpp index 83ec992f3..cd7799379 100644 --- a/native/csrc/catalog/conformance_catalog.cpp +++ b/native/csrc/catalog/conformance_catalog.cpp @@ -1106,8 +1106,15 @@ std::string respond(const std::string& line, Session* session) { } catch (const CatalogError& e) { std::string message; escape_into(e.what(), &message); + // A refusal says whether only this writer's own claim rows made it -- + // what the storage service keeps out of its 2 x TTL latch. + std::string own; + if (e.kind() == CatalogError::Kind::kHeld && session->writer != nullptr) { + own = std::string(",\"own_claims\":") + + (session->writer->refused_by_own_claims() ? "true" : "false"); + } return prefix + "false,\"error\":\"" + error_kind(e.kind()) + - "\",\"message\":" + message + "}"; + "\",\"message\":" + message + own + "}"; } catch (const ClickHouseError& e) { std::string message; escape_into(e.what(), &message); diff --git a/native/csrc/catalog/lease_coordinator.cpp b/native/csrc/catalog/lease_coordinator.cpp index 37779e000..41d79a560 100644 --- a/native/csrc/catalog/lease_coordinator.cpp +++ b/native/csrc/catalog/lease_coordinator.cpp @@ -9,6 +9,9 @@ namespace dmi_catalog { namespace { +// How many recent claim lease_ids to remember (see claimed_ids_). +constexpr size_t kClaimHistory = 16; + // A Seconds setting from whole milliseconds. Whole seconds wherever the // value allows -- what every server parses, and what publish_timeout_ns // already requires -- rounded DOWN, so the server's cap never exceeds the @@ -117,7 +120,9 @@ void LeaseCoordinator::add_write_caps( // designated points while the pipeline runs, so the part commit can // overrun it, and its clock starts when the server starts the query, not // when the client sent it -- a request held up in transit can still land - // up to that delay after the client gave up. + // up to that delay after the client gave up. The storage service + // therefore does not count a refusal by its own claim rows towards its + // 2 x TTL latch (refused_by_own_claims()). const uint64_t deadline = RequestDeadline::current(); // run() set one const uint64_t now = steady_now_ns(); // 0 when the deadline has passed; execute() then sends nothing. @@ -194,10 +199,18 @@ PublisherLease LeaseCoordinator::claim_contested( PublisherLease LeaseCoordinator::claim_with_rival( const std::string& holder, const std::string& lease_id, std::optional rival_lease_id) { + refused_by_own_claims_ = false; claim_insert_sent_ = false; const LeaseHead current = head(); reject_live(current, lease_id); const uint64_t term = current.term + 1; + // Remembered before it is sent: a claim that times out may still land. + // Each id once, moved to the back when it is claimed again (a renewal). + const auto seen = + std::find(claimed_ids_.begin(), claimed_ids_.end(), lease_id); + if (seen != claimed_ids_.end()) claimed_ids_.erase(seen); + claimed_ids_.push_back(lease_id); + if (claimed_ids_.size() > kClaimHistory) claimed_ids_.pop_front(); // Taken before the INSERT goes out, so never after the server stamps the // row: the new lease's deadline counts from here. const uint64_t sent_ns = steady_now_ns(); @@ -269,6 +282,7 @@ LeaseHead LeaseCoordinator::head() const { for (const Row& row : rows) { out.live_until_ns = std::max( out.live_until_ns, parse_u64_field(row[3], "lease expiry")); + out.lease_ids.push_back(row[1]); } return out; } @@ -342,6 +356,13 @@ void LeaseCoordinator::reject_live(const LeaseHead& head, return; } lease_.reset(); + refused_by_own_claims_ = + !head.lease_ids.empty() && + std::all_of(head.lease_ids.begin(), head.lease_ids.end(), + [this](const std::string& id) { + return std::find(claimed_ids_.begin(), claimed_ids_.end(), + id) != claimed_ids_.end(); + }); if (head.claimants > 1) { throw CatalogError( CatalogError::Kind::kHeld, diff --git a/native/csrc/catalog/lease_coordinator.h b/native/csrc/catalog/lease_coordinator.h index 5d402c725..5f9a025e2 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -15,6 +15,7 @@ #define DMI_CATALOG_LEASE_COORDINATOR_H #include +#include #include #include #include @@ -111,6 +112,7 @@ struct LeaseHead { uint64_t expires_at_ns = 0; uint64_t live_until_ns = 0; uint64_t now_ns = 0; + std::vector lease_ids; // every claimant at the head term }; class CatalogError : public std::runtime_error { @@ -157,6 +159,11 @@ class LeaseCoordinator { // never connected, or was not sent because its deadline had passed, // wrote nothing, whatever it failed with. bool claim_insert_sent() const { return claim_insert_sent_; } + // Whether the last refusal (kHeld) came from claim rows this coordinator + // itself inserted, and nobody else's: a claim whose request gave up but + // which the server still executed, late. Such a row expires one TTL after + // it landed and is no rival publisher. + bool refused_by_own_claims() const { return refused_by_own_claims_; } PublisherLease acquire(const std::string& holder); PublisherLease renew(); @@ -198,6 +205,13 @@ class LeaseCoordinator { bool claim_insert_sent_ = false; std::optional lease_; std::string table_; + // The lease_ids of the most recent claim INSERTs this coordinator sent, + // whether or not they were confirmed: a claim that timed out may still + // land. Only a claim from the last TTL or so can still be live, so a + // short history covers it -- each id once, so the renewals of one lease, + // which all claim the same id, cannot crowd the others out. + std::deque claimed_ids_; + bool refused_by_own_claims_ = false; }; } // namespace dmi_catalog diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index ee800d01d..fe0f8c2bb 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -897,8 +897,25 @@ bool CaptureStorageService::ensure_publisher_lease() { void CaptureStorageService::lease_held_elsewhere(const CatalogError& refusal) { const uint64_t now = steady_ns(); const uint64_t ttl = config_.writer.lease_ttl_ns; - if (held_elsewhere_since_ns_ == 0) held_elsewhere_since_ns_ = now; next_claim_ns_ = now + lease_tick_ns(ttl); + if (writer_.refused_by_own_claims()) { + // Refused by this process's own claim row: one whose request gave up + // but which the server still ran -- late, past the cap on the lease + // INSERT (lease_coordinator.cpp says when that can happen). It expires + // one TTL after it landed and is no rival, so it restarts the refusal + // clock rather than counting towards the latch. Sending that claim at + // all meant the head read found no live rival, so a rival's earlier + // refusals ended there too. Without this, refusals by a rival that has + // since left, then by our own late row, could add up to 2 x TTL and + // latch the service against itself. + held_elsewhere_since_ns_ = 0; + record_error(std::string("publisher lease refused by this service's " + "own earlier claim, which landed after its " + "request gave up; retrying: ") + + refusal.what()); + return; + } + if (held_elsewhere_since_ns_ == 0) held_elsewhere_since_ns_ = now; // Our own dropped row is dead within one TTL of the loss, and a handover // (a rival that stops, releasing with a tombstone) ends sooner still. A // refusal that has lasted 2 x TTL is a publisher that means to stay. diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index 93ac28dc6..cf588d711 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -38,6 +38,8 @@ // (clickhouse_catalog.py, publish_snapshot). Only a foreign lease that stays // live for 2 x TTL is fatal: the service stops (snapshot().failed), writes // one line to stderr, and flush() rethrows the refusal naming the holder. +// A refusal by one of the service's own claim rows -- a claim that landed +// after its request gave up -- is no rival and restarts that clock. // // Bounded by the lease. Every catalog request the service makes while it // holds the lease -- the renewal's own, and every one an index pass or a @@ -247,7 +249,8 @@ class CaptureStorageService { // and is no longer quarantined. Never throws. Requires lease_mutex_. bool ensure_publisher_lease(); // Another holder refused a claim or renewal; latches once that has lasted - // 2 x TTL. Call from the catch block. Requires lease_mutex_. + // 2 x TTL. A refusal by the service's own claim rows restarts the clock + // instead. Call from the catch block. Requires lease_mutex_. void lease_held_elsewhere(const CatalogError& refusal); void publish_lease_state(); // requires lease_mutex_ // Sets a pack aside for good; flush() reports it. Requires cycle_mutex_. diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 6d7ee53a6..0b40216a6 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -278,9 +278,9 @@ def test_the_reference_reader_sees_the_same_captures(fake_s3, tmp_path): class _Switch: """A TCP forwarder in front of an HTTP server -- ClickHouse's HTTP port, or the fake S3 -- that can be cut (connections refused), stalled - (connections accepted, never answered), made to stall only the requests - a predicate picks, or to hold the first request a predicate picks back - for a while. Every + (connections accepted, never answered), made to hold lease INSERTs back + and deliver them late, to stall only the requests a predicate picks, or + to hold the first request a predicate picks back for a while. Every native client opens one connection per request, so one request is one connection here.""" @@ -290,6 +290,7 @@ def __init__(self, host: str, port: int): self.port = self._listener.getsockname()[1] self._up = True self._stalled = False + self._late_by = 0.0 # seconds a lease INSERT is held back; 0 = never # A predicate over one whole request (head and body): matching # requests are held open and never answered. self._stall_if = None @@ -324,7 +325,8 @@ def _accept(self): if not self._up: client.close() continue - if self._stall_if is not None or self._slow_once is not None: + if (self._late_by > 0 or self._stall_if is not None + or self._slow_once is not None): threading.Thread(target=self._look_then_route, args=(client,), daemon=True).start() continue @@ -354,9 +356,12 @@ def _pump(source, sink): pass def _look_then_route(self, client): - """Read one HTTP request and route it: a request stall_requests() - picks is never answered, the first request slow_once() picks is - forwarded late, and anything else goes straight through.""" + """Read one HTTP request and route it: a lease INSERT held back by + deliver_lease_inserts_late() reaches the server only after that delay + -- long after the client gave up on it -- and nobody hears the + answer; a request stall_requests() picks is never answered; the first + request slow_once() picks is forwarded late; anything else goes + straight through.""" request = b"" continued = False try: @@ -397,18 +402,37 @@ def _look_then_route(self, client): if slow is not None and slow[0](request): self._slow_once = None time.sleep(slow[1]) + late_by = self._late_by + late = (late_by > 0 and b"INSERT INTO" in request + and b"_publisher_lease" in request) + if late: + time.sleep(late_by) try: upstream = socket.create_connection(self._target) upstream.sendall(request) except OSError: client.close() return + if late: + # Nobody is listening any more; the server runs it regardless. + client.close() + upstream.settimeout(10.0) + try: + while upstream.recv(65536): + pass + except OSError: + pass + upstream.close() + return with self._lock: self._sockets |= {client, upstream} for source, sink in ((client, upstream), (upstream, client)): threading.Thread(target=self._pump, args=(source, sink), daemon=True).start() + def deliver_lease_inserts_late(self, late_by: float): + self._late_by = late_by + def stall_requests(self, predicate): """Hold every new request `predicate(request_bytes)` picks open and never answer it; the rest go through.""" @@ -438,6 +462,7 @@ def stall(self): def restore(self): self._up = True self._stalled = False + self._late_by = 0.0 self._stall_if = None self._slow_once = None @@ -1570,6 +1595,64 @@ def test_a_rival_that_stops_within_two_ttls_does_not_latch( assert _latch_lines(capfd.readouterr().err) == [] +def test_a_late_landing_claim_of_its_own_does_not_latch_the_service( + fake_s3, tmp_path, capfd): + """The lease INSERT's server-side cap cannot cover a request held up in + transit: the server starts the clock only when the statement reaches + it. Such a claim lands after the client gave up and quarantined, and its + row then refuses the service's own next claim. Refusals by a rival that + had since left and by that row of our own added up to 2 x TTL, and the + service latched "held by another publisher" against itself. A refusal + by the service's own claim row now restarts the refusal clock.""" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + knobs = dict(reconcile_on_start=False, lease_ttl_s=3.0, + publish_timeout_s=1) + first = _service(_storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + holder="first-publisher", **knobs), tmp_path / "first") + rival = _service(_storage_config( + fake_s3, catalog.table_prefix, holder="rival-publisher", + start_lease_wait_s=10.0, **knobs), tmp_path / "rival") + first.start() + try: + # A cut quarantines the first service; the rival takes over. + switch.cut() + rival.start() + switch.restore() + # The first service's quarantine ends and the rival refuses it: + # the refusal clock starts. + _wait_for(lambda: first.snapshot()["lease_state"] == "reacquiring", + timeout_s=10.0) + refused_at = time.monotonic() + # Well inside 2 x TTL of refusals the rival leaves (a handover), + # and the first service's next claim is delivered 1.5 s late: + # the 1 s bound on a claim made without a lease (lease_ttl_s / 3) + # gives up first, and it quarantines. + time.sleep(max(0.0, refused_at + 4.0 - time.monotonic())) + switch.deliver_lease_inserts_late(1.5) + rival.stop() + _wait_for(lambda: first.snapshot()["lease_state"] == "quarantined", + timeout_s=3.0) + switch.restore() + # The late claim lands inside the quarantine and outlives it by + # about a second, refusing the first service's next claim more + # than 2 x TTL after the rival's first refusal. + _wait_for(lambda: first.snapshot()["lease_state"] == "held" + or first.snapshot()["failed"], timeout_s=10.0) + snapshot = first.snapshot() + assert time.monotonic() - refused_at > 2 * 3.0, snapshot + assert snapshot["failed"] is False, snapshot + assert snapshot["lease_state"] == "held", snapshot + first.rethrow_if_failed() + finally: + first.stop() + rival.stop() + switch.close() + + assert _latch_lines(capfd.readouterr().err) == [] + + _HOLD_LEASE = """ import json, sys, time from dmi.storage.native_capture import ( diff --git a/tests/test_native_lease_request_bound.py b/tests/test_native_lease_request_bound.py index a4a5fac8c..e5ed75c78 100644 --- a/tests/test_native_lease_request_bound.py +++ b/tests/test_native_lease_request_bound.py @@ -332,6 +332,62 @@ def test_a_slow_but_healthy_head_read_does_not_fail_the_claim(fake, driver): assert claimed["ok"], claimed +def test_renewals_do_not_crowd_earlier_claims_out_of_the_history( + fake, driver): + """The history of recent claim lease_ids is what tells the service's own + late row from a rival's. Each renewal pushed its (unchanged) lease_id + again, so sixteen renewals pushed out a claim that could still land.""" + assert driver.open()["ok"] + earlier = str(uuid.uuid4()) + assert driver.call(op="claim", holder="h", lease_id=earlier)["ok"] + driver.call(op="discard_local_lease") # as a quarantine drops it + assert driver.call(op="acquire", holder="h")["ok"] + for _ in range(20): + assert driver.call(op="renew")["ok"] + driver.call(op="discard_local_lease") + + fake.head_rows = f"1\t{earlier}\th\t{2 * 10**18}\t{10**18}\n" + refused = driver.call(op="acquire", holder="h") + assert refused["error"] == "PublisherLeaseHeldError", refused + assert refused["own_claims"] is True, refused + + +def test_a_refusal_by_the_writers_own_claim_row_is_attributed_to_it( + fake, driver): + """A claim whose request gave up can still land, and then refuses the + writer's next claim. The refusal names it as the writer's own, which the + storage service keeps out of its 2 x TTL latch; a rival's row is not.""" + assert driver.open()["ok"] + mine = str(uuid.uuid4()) + assert driver.call(op="claim", holder="h", lease_id=mine)["ok"] + driver.call(op="discard_local_lease") # as a quarantine drops it + + # Our earlier claim row is the live head; a fresh lease_id is refused. + fake.head_rows = f"1\t{mine}\th\t{2 * 10**18}\t{10**18}\n" + refused = driver.call(op="acquire", holder="h") + assert refused["error"] == "PublisherLeaseHeldError", refused + assert refused["own_claims"] is True, refused + + # Contested between our row and a rival's: not ours alone. + rival = str(uuid.uuid4()) + fake.head_rows = (f"1\t{rival}\trival\t{2 * 10**18}\t{10**18}\n" + f"1\t{mine}\th\t{2 * 10**18}\t{10**18}\n") + refused = driver.call(op="acquire", holder="h") + assert refused["error"] == "PublisherLeaseHeldError", refused + assert refused["own_claims"] is False, refused + + # A coordinator that never claimed `mine` sees a rival in it. + other = _Driver(fake.port) + try: + assert other.open()["ok"] + fake.head_rows = f"1\t{mine}\th\t{2 * 10**18}\t{10**18}\n" + refused = other.call(op="acquire", holder="h2") + assert refused["error"] == "PublisherLeaseHeldError", refused + assert refused["own_claims"] is False, refused + finally: + other.close() + + # --- the storage service's configuration -------------------------------------- From d8ff47ea2c51c7f282def3389902beb9b813a3a8 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 00:55:56 -0400 Subject: [PATCH 05/13] Renew the publisher lease from the moment start() takes it start() took the lease, swept the spool and reconciled the bucket, and only then started the lease thread, so nothing renewed the lease while a large bucket was listed: listing pages and their committed_pack_ids reads never renew, and the indexer's keep_lease hook runs only once a missing pack is being committed. Once the lease deadline passed, the next lease-locked step abandoned the lease (LeaseScope), and a crash-window pack found after that hit commit()'s "holds no publisher lease", which start() rethrew -- where main re-claimed its own lapsed row and indexed the pack. With nothing to index, start() returned with the lease quarantined, and the snapshot said "held" over a dead row all through the listing. stop() had the same gap at the other end: it woke the loop and the lease thread together, and the lease thread left while the loop's last cycle still ran. - start() starts the lease thread as soon as it holds the lease, before the sweep and the reconcile (sweep_and_reconcile_at_start). A start that fails after that stops the lease thread before releasing. - stop() joins the loop first and only then the lease thread, which now has a stop flag of its own. - A lease lost while the start-time reconcile runs -- to a quarantine or to another holder -- no longer fails start(). That is the running service's case, and the loop handles it as it does there: a fresh lease once the quarantine ends, or the latch after 2 x TTL of a rival. The pass it cut short is owed (reconcile_owed_), and the loop runs it once it holds a lease again. A reconcile that fails otherwise (a listing error) is recorded as before. Tests first, in tests/test_native_capture_storage_live.py, TTL 3 s: - the first LIST delayed 6 s at start, with and without a crash-window pack: before, start() raised "holds no publisher lease" (with the pack) or returned quarantined (without), and the snapshot said "held" over a dead row from 2.9 s; now the lease is held and renewed through the listing and the pack is reconciled and indexed. - the lease thread's renewal stalled while a 2.5 s listing runs, so the lease quarantines before the crash-window pack is found: with start() rethrowing it raised; now start() returns quarantined, and the loop takes a fresh lease and indexes the pack. - stop() while the loop's last cycle reads a pack for 4 s: with the old stop order, "held" over a dead row from 2.97 s; now the cycle indexes the pack and the lease is released after it. The storage live suite and the CPU lease-bound tests pass. --- native/csrc/catalog/storage_service.cpp | 115 ++++++++---- native/csrc/catalog/storage_service.h | 21 ++- tests/test_native_capture_storage_live.py | 207 +++++++++++++++++++++- 3 files changed, 300 insertions(+), 43 deletions(-) diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index fe0f8c2bb..483c4b9a3 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -171,6 +171,49 @@ void CaptureStorageService::start() { acquire_lease_at_start(); // throws kHeld if another publisher keeps it } + // The lease renews from here on, not once start() is done: the sweep and + // the reconcile below can outlast the lease deadline (a large bucket lists + // for longer than a TTL), and a lease nobody renewed is abandoned at the + // next lease-locked step, when it is reported held over a dead row until + // then. + { + std::lock_guard lock(wake_mutex_); + stop_requested_ = false; + lease_stop_requested_ = false; + kick_ = false; + } + lease_thread_ = std::thread([this] { keep_lease(); }); + try { + sweep_and_reconcile_at_start(); + } catch (...) { + // start() must not return holding a lease stop() will never release, + // nor leave the lease thread renewing it. + stop_lease_thread(); + try { + LeaseScope lease(this); + if (writer_.held_lease() != nullptr) writer_.release_lease(); + } catch (...) { + } + throw; + } + last_reconcile_ns_ = steady_ns(); + + { + std::lock_guard lock(wake_mutex_); + kick_ = false; + } + { + LeaseScope lease(this); // publishes the lease state + } + { + std::lock_guard lock(state_mutex_); + state_.running = !state_.failed; + } + started_ = true; + thread_ = std::thread([this] { loop(); }); +} + +void CaptureStorageService::sweep_and_reconcile_at_start() { // After the lease, never before, so a second process pointed at this spool // usually learns that the catalog is held before it can delete a live // sink's .open files. Only usually: a holder that is quarantined has let @@ -181,11 +224,6 @@ void CaptureStorageService::start() { std::vector recovered; std::string error; if (spool_.Recover(&recovered, &error) != dmi_store::SpoolStatus::kOk) { - try { - LeaseScope lease(this); - if (writer_.held_lease() != nullptr) writer_.release_lease(); - } catch (...) { - } throw std::runtime_error("storage service: spool recovery failed: " + error); } @@ -193,43 +231,29 @@ void CaptureStorageService::start() { state_.swept_on_start = recovered.size(); } - // A failed pass is not fatal -- the bucket is still there next time -- but a - // lost lease is, and start() must not return holding a lease stop() will - // never release. + // A failed pass is not fatal -- the bucket is still there next time. Nor + // is a lease lost while it runs, to a quarantine or to another holder: + // that is the running service's case, and the loop handles it as it does + // there, taking a fresh lease once it can (or latching after 2 x TTL of a + // rival). The pass it cut short is owed, and the loop runs it once it + // holds a lease again. if (config_.reconcile_on_start) { try { reconcile(); } catch (const CatalogError& exc) { if (is_lease_refusal(exc)) { - try { - LeaseScope lease(this); - if (writer_.held_lease() != nullptr) writer_.release_lease(); - } catch (...) { - } - throw; + reconcile_owed_ = true; + record_error(std::string("reconcile at start lost the publisher " + "lease; the loop reconciles once it holds " + "one again: ") + + exc.what()); + } else { + record_error(std::string("reconcile at start failed: ") + exc.what()); } - record_error(std::string("reconcile at start failed: ") + exc.what()); } catch (const std::exception& exc) { record_error(std::string("reconcile at start failed: ") + exc.what()); } } - last_reconcile_ns_ = steady_ns(); - - { - std::lock_guard lock(wake_mutex_); - stop_requested_ = false; - kick_ = false; - } - { - LeaseScope lease(this); // publishes the lease state - } - { - std::lock_guard lock(state_mutex_); - state_.running = true; - } - started_ = true; - lease_thread_ = std::thread([this] { keep_lease(); }); - thread_ = std::thread([this] { loop(); }); } void CaptureStorageService::stop() { @@ -239,7 +263,9 @@ void CaptureStorageService::stop() { } wake_.notify_all(); if (thread_.joinable()) thread_.join(); - if (lease_thread_.joinable()) lease_thread_.join(); + // Only after the loop: its last cycle may still be indexing, and the + // lease has to keep renewing until that is done. + stop_lease_thread(); std::lock_guard cycle(cycle_mutex_); if (started_) { started_ = false; @@ -264,6 +290,15 @@ void CaptureStorageService::stop() { state_.running = false; } +void CaptureStorageService::stop_lease_thread() { + { + std::lock_guard lock(wake_mutex_); + lease_stop_requested_ = true; + } + wake_.notify_all(); + if (lease_thread_.joinable()) lease_thread_.join(); +} + bool CaptureStorageService::flush(double timeout_s) { const auto deadline = std::chrono::steady_clock::now() + std::chrono::duration_cast( @@ -411,10 +446,14 @@ CaptureStorageService::CycleOutcome CaptureStorageService::run_cycle() { // 3. Index them. index_or_owe(std::move(to_index)); - // 4. Reconcile on its interval. The lease thread keeps the lease alive. - if (catalog && config_.reconcile_interval_ns > 0 && - steady_ns() - last_reconcile_ns_ >= config_.reconcile_interval_ns) { + // 4. Reconcile on its interval, or when the pass at start() lost the + // lease before it finished. The lease thread keeps the lease alive. + if (catalog && + (reconcile_owed_ || + (config_.reconcile_interval_ns > 0 && + steady_ns() - last_reconcile_ns_ >= config_.reconcile_interval_ns))) { reconcile(); + reconcile_owed_ = false; last_reconcile_ns_ = steady_ns(); } @@ -670,8 +709,8 @@ void CaptureStorageService::keep_lease() { while (true) { { std::unique_lock lock(wake_mutex_); - wake_.wait_for(lock, tick, [this] { return stop_requested_; }); - if (stop_requested_) return; + wake_.wait_for(lock, tick, [this] { return lease_stop_requested_; }); + if (lease_stop_requested_) return; } { std::lock_guard lock(state_mutex_); diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index cf588d711..cce9be764 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -187,8 +187,11 @@ class CaptureStorageService { // Ensure the catalog schema, take the publisher lease (waiting up to // start_lease_wait_ns for another holder's to expire, or for a claim that // timed out to go through), sweep the spool, reconcile once, then start - // the background cycle. Throws if the lease is still held by another - // publisher when the wait ends, or its claim still times out. + // the background cycle. The lease renews from the moment it is taken. + // Throws if the lease is still held by another publisher when the wait + // ends, or its claim still times out. A lease lost while the reconcile + // runs does not fail start(): the loop takes a fresh one, as it would + // later, and reconciles then. void start(); // Run cycles until one finds the spool empty with every uploaded pack @@ -224,6 +227,11 @@ class CaptureStorageService { class LeaseScope; void loop(); + // start()'s spool sweep and reconcile, with the lease held and the lease + // thread renewing it. Requires cycle_mutex_. + void sweep_and_reconcile_at_start(); + // Stops the lease thread and waits for it. + void stop_lease_thread(); CycleOutcome run_cycle(); // requires cycle_mutex_ // Indexes refs in bounded batches, appending every ref that did not index // to *unindexed. Only a lost lease propagates; other failures are recorded. @@ -284,6 +292,9 @@ class CaptureStorageService { // hammer the lease table. Guarded by lease_mutex_. uint64_t next_claim_ns_ = 0; uint64_t last_reconcile_ns_ = 0; + // The reconcile at start() lost the lease before it finished; the loop + // runs one once it holds a lease again. Guarded by cycle_mutex_. + bool reconcile_owed_ = false; int failure_streak_ = 0; // consecutive failed cycles, for the backoff // Uploaded, so gone from the spool, but not yet in the catalog. std::vector pending_index_; @@ -292,11 +303,13 @@ class CaptureStorageService { std::thread thread_; // Renews on its own schedule, so neither the cycle backoff nor a slow - // upload can let the lease lapse while the service still runs. + // upload can let the lease lapse while the service still runs. It runs + // from the moment start() takes the lease until the loop has stopped. std::thread lease_thread_; std::mutex wake_mutex_; std::condition_variable wake_; - bool stop_requested_ = false; + bool stop_requested_ = false; // the loop's; guarded by wake_mutex_ + bool lease_stop_requested_ = false; // the lease thread's; likewise // Set when a lease is re-acquired, so a loop in a long backoff indexes // what is owed now rather than after its wait. Guarded by wake_mutex_. bool kick_ = false; diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 0b40216a6..1fd7c6a43 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -741,7 +741,7 @@ def test_a_batch_over_the_budget_splits_until_every_pack_indexes( service = _load_native_store_extension().StorageService(native) service.start() try: - assert service.flush(30.0) + service.flush(30.0) snapshot = service.snapshot() finally: service.stop() @@ -1411,6 +1411,211 @@ def test_start_survives_a_first_lease_read_slower_than_its_bound( switch.close() +def _listing(request: bytes) -> bool: + line = request.partition(b"\r\n")[0] + return line.startswith(b"GET ") and b"list-type=2" in line + + +def _upload_behind_the_service(spool_root: Path, endpoint: str) -> list: + """Upload what the spool holds without indexing it -- the crash window + between an upload and its index -- and return the refs.""" + store = _Driver(STORE_DRIVER) + try: + uploaded = store.call( + op="upload_pending", endpoint=endpoint, bucket=BUCKET, + region=REGION, access=ACCESS, secret=SECRET, token=None, + insecure=True, connect_timeout=5, read_timeout=15, max_attempts=4, + store_id="s3", root=str(spool_root), spool_max_bytes=1 << 40, + limit=-1, max_workers=4, max_in_flight_bytes=1 << 30) + assert uploaded["ok"], uploaded + finally: + store.close() + assert _ready(spool_root) == [] + return uploaded["refs"] + + +def _sample_during(call, service, client, prefix, *, every=0.1): + """Run call() while sampling (t, lease_state, row live) from another + thread, as _sample_lease does; the row is read only while the service + says "held", since the lease table may not exist before that.""" + log = [] + done = threading.Event() + origin = time.monotonic() + + def _sample(): + while not done.is_set(): + state = service.snapshot()["lease_state"] + live = (_lease_row_live(client, prefix) if state == "held" + else None) + log.append((round(time.monotonic() - origin, 2), state, live)) + time.sleep(every) + + sampler = threading.Thread(target=_sample, daemon=True) + sampler.start() + try: + call() + finally: + done.set() + sampler.join(timeout=10) + return log + + +@pytest.mark.parametrize("crash_window_pack", [True, False]) +def test_the_lease_renews_while_start_reconciles( + fake_s3, tmp_path, crash_window_pack): + """start() takes the lease, then sweeps the spool and reconciles the + bucket, and only then started the lease thread: nothing renewed the + lease while a large bucket was listed. Once its deadline passed, the + first lease-locked step abandoned it, so a crash-window pack found after + that could not be indexed and start() failed, where main re-claimed its + own lapsed row and indexed it; with nothing to index, start() returned + with the lease quarantined, and the snapshot said "held" over a dead row + all through the listing. The lease thread now runs from the moment the + lease is taken. One slow listing page (6 s, two TTLs) stands in for a + bucket of many pages.""" + spool_root = tmp_path / "spool" + tensors = {} + if crash_window_pack: + tensors = _stage(spool_root, range(2)) + _upload_behind_the_service(spool_root, fake_s3) + s3 = _Switch.to_url(fake_s3) + with _catalog() as (client, catalog): + config = _storage_config(s3.url, catalog.table_prefix, + lease_ttl_s=3.0, publish_timeout_s=1) + service = _service(config, spool_root) + s3.slow_once(_listing, 6.0) + try: + log = _sample_during(service.start, service, client, + catalog.table_prefix) + snapshot = service.snapshot() + assert snapshot["lease_state"] == "held", snapshot + assert snapshot["reconcile_passes"] == 1, snapshot + assert snapshot["reconciled_packs"] == int(crash_window_pack), \ + snapshot + assert snapshot["indexed_packs"] == int(crash_window_pack), \ + snapshot + assert snapshot["lease_renewals"] >= 3, snapshot + assert not _held_but_dead(log), log + service.flush(30.0) + service.rethrow_if_failed() + finally: + service.stop() + s3.close() + + if crash_window_pack: + captures = _read_all(_storage_config(fake_s3, + catalog.table_prefix)) + assert sorted(captures) == sorted(tensors) + + +def test_the_lease_renews_until_the_loops_last_cycle_is_done( + fake_s3, tmp_path): + """stop() woke the loop and the lease thread together, and the lease + thread left at once while the loop's last cycle still ran: a pass + reading a pack then found its lease abandoned at the commit, and the + snapshot said "held" over a dead row until then. The lease thread now + stops only after the loop has.""" + spool_root = tmp_path / "spool" + s3 = _Switch.to_url(fake_s3) + with _catalog() as (client, catalog): + config = _storage_config(s3.url, catalog.table_prefix, + reconcile_on_start=False, lease_ttl_s=3.0, + publish_timeout_s=1) + service = _service(config, spool_root) + service.start() + reads = [] + + def _first_read(request: bytes) -> bool: + if _ranged_get(request): + reads.append(time.monotonic()) + return True + return False + + try: + s3.slow_once(_first_read, 4.0) # past the lease deadline + tensors = _stage(spool_root, range(2)) + _wait_for(lambda: reads, timeout_s=10.0) + log = _sample_during(service.stop, service, client, + catalog.table_prefix) + snapshot = service.snapshot() + finally: + service.stop() + s3.close() + + assert not _held_but_dead(log), log + assert snapshot["indexed_packs"] == 1, snapshot + assert snapshot["lease_state"] == "released", snapshot + captures = _read_all(_storage_config(fake_s3, catalog.table_prefix)) + assert sorted(captures) == sorted(tensors) + + +def _lease_insert(request: bytes) -> bool: + body = request.partition(b"\r\n\r\n")[2] + return body.startswith(b"INSERT") and b"_publisher_lease` (term" in body + + +def test_a_lease_lost_while_start_reconciles_is_retaken_and_the_pass_rerun( + fake_s3, tmp_path): + """A lease lost while start() reconciled failed start(): the pass's + commit found no lease and start() rethrew, although a quarantine is the + recoverable kind everywhere else. Here the lease thread's renewal stalls + while the listing is slow, so the lease quarantines before the + crash-window pack is found. start() now returns, and the loop takes a + fresh lease once the quarantine ends and runs the reconcile it owes.""" + spool_root = tmp_path / "spool" + tensors = _stage(spool_root, range(2)) + _upload_behind_the_service(spool_root, fake_s3) + s3 = _Switch.to_url(fake_s3) + catalog_switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + knobs = dict(lease_ttl_s=3.0, publish_timeout_s=1, + clickhouse_request_timeout_s=20.0) + # The schema first, directly, so that the service's claim is the + # first lease INSERT through the switch. + warm = _service(_storage_config(fake_s3, catalog.table_prefix, + reconcile_on_start=False, **knobs), + tmp_path / "warm") + warm.start() + warm.stop() + + seen = [] + + def _renewal(request: bytes) -> bool: + if not _lease_insert(request): + return False + seen.append(request) + return len(seen) > 1 # the claim goes through, renewals stall + + catalog_switch.stall_requests(_renewal) + s3.slow_once(_listing, 2.5) # past the first renewal, due at 1 s + service = _service(_storage_config( + s3.url, catalog.table_prefix, + clickhouse_port=catalog_switch.port, **knobs), spool_root) + service.start() + try: + snapshot = service.snapshot() + assert snapshot["lease_state"] == "quarantined", snapshot + assert snapshot["indexed_packs"] == 0, snapshot + assert "reconcile at start lost the publisher lease" in \ + snapshot["last_error"], snapshot + + catalog_switch.restore() + _wait_for(lambda: service.snapshot()["reconciled_packs"] == 1, + timeout_s=15.0) + service.flush(30.0) + snapshot = service.snapshot() + assert snapshot["indexed_packs"] == 1, snapshot + assert snapshot["lease_state"] == "held", snapshot + service.rethrow_if_failed() + finally: + service.stop() + catalog_switch.close() + s3.close() + + captures = _read_all(_storage_config(fake_s3, catalog.table_prefix)) + assert sorted(captures) == sorted(tensors) + + def test_lease_requests_that_keep_timing_out_name_the_knobs_that_bound_them( fake_s3, tmp_path): """On a catalog too slow for its lease the service went round -- a claim From d1a87c487eabb5238133ad035d5d7bd3cdc31503 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 01:07:35 -0400 Subject: [PATCH 06/13] Renew the publisher lease before every request made under its lock Every request made under the lease lock has to be answered by the lease deadline, and a pass could renew only at the indexer's keep_lease hook, before its catalog writes. Between two hooks ran several requests with no chance to renew: allocate_version's two max() reads, its claim INSERT and read-back (and last_published_version on a first pass); the publish's watermark INSERT, owners and member-count reads and the inventory commit. The stretch and the renewal after it had to fit before the deadline, so against a catalog slow but healthy -- each request well inside publish_timeout -- the renewal at the next hook started with too little time left, timed out, and quarantined the writer. At the defaults with 3 s INSERTs and 1 s reads: a renewal leaves the lease 4 s old, allocate_version adds 6 s, and the renewal due at the next hook needs 5 s of the 4.9 s left. Every pass failed that way, so flush() never drained; main drained it, bounding nothing. - RequestDeadline can carry a before_request hook, which execute() runs once per call before it reads the deadline, so the hook may move it. Only the innermost scope's hook runs, and never inside itself, so the lease coordinator's own scope keeps the requests of a renewal the hook started from starting another. - LeaseScope's hook is keep_lease_in_pass(): renew when due (a third of the TTL after the claim that stamped the row was sent), before every request a stretch under the lease lock sends, reads included, the inventory commit too. A renewal then starts with the lease at most a third of the TTL plus one request old. IndexerConfig::keep_lease, which did this before catalog writes only, is gone. - The lease thread wakes when the renewal falls due (a tick at most), not on a fixed tick, so the renewal a pass leaves due when it lets go of the lock starts then, not up to a sixth of the TTL later. What cannot be kept: a catalog so slow that one request plus a renewal does not fit in what a renewal leaves -- at a 15 s TTL, 4 s INSERTs with 1 s reads -- still loses the lease pass after pass, now while its row is still live rather than drained over a dead one as main did; it needs a longer lease_ttl_s (the next commit makes the service say so). Test first, in tests/test_native_capture_storage_live.py: the TCP switch can now hold every request back by a delay a function picks, and a catalog answering INSERTs 0.6 s late and reads 0.2 s late against a 3 s TTL (3 s and 1 s at the default 15 s) indexes two packs with the lease held throughout. Before: flush() timed out with both packs owed, "index failed: ... Timeout ... bounded by the lease deadline". The storage and catalog-lease live suites and the CPU lease-bound tests pass. --- native/csrc/catalog/clickhouse_client.cpp | 21 +++++- native/csrc/catalog/clickhouse_client.h | 18 ++++- native/csrc/catalog/indexer.cpp | 9 --- native/csrc/catalog/indexer.h | 7 -- native/csrc/catalog/storage_service.cpp | 57 +++++++++------ native/csrc/catalog/storage_service.h | 20 +++--- tests/test_native_capture_storage_live.py | 87 +++++++++++++++++++++-- 7 files changed, 165 insertions(+), 54 deletions(-) diff --git a/native/csrc/catalog/clickhouse_client.cpp b/native/csrc/catalog/clickhouse_client.cpp index b25713dbe..f48431ed6 100644 --- a/native/csrc/catalog/clickhouse_client.cpp +++ b/native/csrc/catalog/clickhouse_client.cpp @@ -124,6 +124,8 @@ std::string url_encode(const std::string& value) { // The innermost RequestDeadline on this thread; each links to the one it // nests in. thread_local RequestDeadline* innermost_deadline = nullptr; +// Set while a before_request hook runs on this thread. +thread_local bool in_before_request = false; // "60 s", "0.25 s": a timeout for a message. std::string seconds_text(double seconds) { @@ -244,8 +246,10 @@ RequestDeadline::RequestDeadline(uint64_t deadline_ns, std::string bound) } RequestDeadline::RequestDeadline(std::function deadline_ns, - std::string bound) + std::string bound, + std::function before_request) : moving_ns_(std::move(deadline_ns)), bound_(std::move(bound)), + before_request_(std::move(before_request)), outer_(innermost_deadline) { innermost_deadline = this; } @@ -266,6 +270,18 @@ uint64_t RequestDeadline::current(std::string* bound) { return tightest; } +void RequestDeadline::before_request() { + const RequestDeadline* scope = innermost_deadline; + if (scope == nullptr || !scope->before_request_ || in_before_request) { + return; + } + struct Running { + Running() { in_before_request = true; } + ~Running() { in_before_request = false; } + } running; + scope->before_request_(); +} + void validate(const ClickHouseConnection& c) { if (c.scheme != "http" && c.scheme != "https") { throw ClickHouseError("clickhouse scheme must be \"http\" or \"https\""); @@ -447,6 +463,9 @@ ClickHouseClient::~ClickHouseClient() = default; std::vector ClickHouseClient::execute( const std::string& query, const Params& params, const std::map& settings, int* attempts) const { + // First, so that what it does -- a lease renewal -- moves the deadline + // before this request reads it. + RequestDeadline::before_request(); const std::string statement = substitute(query, params); const bool read = is_read_statement(statement); diff --git a/native/csrc/catalog/clickhouse_client.h b/native/csrc/catalog/clickhouse_client.h index 595fa179a..668236e3d 100644 --- a/native/csrc/catalog/clickhouse_client.h +++ b/native/csrc/catalog/clickhouse_client.h @@ -62,6 +62,14 @@ uint64_t steady_now_ns(); // The publisher lease is what uses it (lease_coordinator.h): while a lease is // held, every request its holder makes has to be answered before the lease // row can expire, not only the lease's own statements. +// +// A scope may also carry a hook that execute() runs once before each request +// it sends, before the deadline is read -- so the hook can move it: the +// storage service renews its lease there when that falls due, whatever the +// request. Only the innermost scope's hook runs, so a scope nested inside +// one (the lease coordinator's, around a renewal the hook started) keeps the +// hook from running for its own requests; and a hook never runs inside +// itself. class RequestDeadline { public: // A fixed deadline, steady ns. @@ -69,7 +77,8 @@ class RequestDeadline { // A deadline read afresh before every request attempt, so that its owner // can move it while the scope lives (a lease that renews mid-pass). 0 // means no deadline is in force at the moment. - RequestDeadline(std::function deadline_ns, std::string bound); + RequestDeadline(std::function deadline_ns, std::string bound, + std::function before_request = {}); ~RequestDeadline(); RequestDeadline(const RequestDeadline&) = delete; RequestDeadline& operator=(const RequestDeadline&) = delete; @@ -77,11 +86,15 @@ class RequestDeadline { // The tightest deadline in force on this thread, 0 if none; `bound`, when // given, receives what set it. static uint64_t current(std::string* bound = nullptr); + // Runs the innermost scope's before_request hook, if it has one and it is + // not already running. What the hook throws propagates. + static void before_request(); private: uint64_t fixed_ns_ = 0; std::function moving_ns_; std::string bound_; + std::function before_request_; RequestDeadline* outer_; }; @@ -199,7 +212,8 @@ class ClickHouseClient { // milliseconds left (rounded down, so never past it), no attempt starts // with less than a millisecond left, and no backoff sleeps past it -- the // last attempt's error is thrown instead, saying so. A timeout's message - // names the bound that ended it. + // names the bound that ended it. The innermost scope's before_request + // hook runs first, once per call. // // Reads also carry wait_end_of_query=1, so the server buffers the result // and an exception part-way through it arrives as an error status rather diff --git a/native/csrc/catalog/indexer.cpp b/native/csrc/catalog/indexer.cpp index 8e8888d10..25793b897 100644 --- a/native/csrc/catalog/indexer.cpp +++ b/native/csrc/catalog/indexer.cpp @@ -133,10 +133,6 @@ IndexResultData NativeIndexer::index(const std::vector& refs) { return commit(&planned); } -void NativeIndexer::keep_lease() const { - if (config_.keep_lease) config_.keep_lease(); -} - IndexPlan NativeIndexer::plan(const std::vector& refs) { IndexPlan planned; IndexResultData& result = planned.result; @@ -320,13 +316,11 @@ IndexResultData NativeIndexer::commit(IndexPlan* planned) { planned->rows.clear(); if (!all_rows.empty() || !indexed.empty()) { - keep_lease(); uint64_t version = allocate_version(); uint64_t descriptor_inserts = 0; const auto write_batches = [&](uint64_t at_version) { for (size_t start = 0; start < all_rows.size(); start += config_.max_rows_per_insert) { - keep_lease(); std::vector chunk( all_rows.begin() + static_cast(start), all_rows.begin() + @@ -377,7 +371,6 @@ IndexResultData NativeIndexer::commit(IndexPlan* planned) { // competitor published, so the head read on the first allocation // is stale at exactly the moment the cross-check matters. published_version_.reset(); - keep_lease(); version = allocate_version(); write_batches(version); continue; @@ -391,8 +384,6 @@ IndexResultData NativeIndexer::commit(IndexPlan* planned) { "could not publish a catalog snapshot after " + std::to_string(config_.max_publish_attempts) + " attempts"); } - // No keep_lease() here: the publish has just renewed, and a renewal - // that failed now would leave the packs it made visible unrecorded. if (!indexed.empty()) { writer_->commit_packs(RenderPackRows(indexed), version); } diff --git a/native/csrc/catalog/indexer.h b/native/csrc/catalog/indexer.h index 4bff76965..d6e7050fa 100644 --- a/native/csrc/catalog/indexer.h +++ b/native/csrc/catalog/indexer.h @@ -33,12 +33,6 @@ struct IndexerConfig { // published head to move between an allocation and its publish, which // only something outside this call can do. Left empty, this is nothing. std::function after_allocate; - // Called before each catalog write commit() makes -- the version claim, - // each descriptor chunk, the inventory commit -- so that a long pass can - // renew its lease when that falls due, instead of running the lease down - // while its caller holds the lease lock. The publish renews on its own. - // What it throws propagates. Unset: nothing. - std::function keep_lease; }; struct IndexFailureData { @@ -96,7 +90,6 @@ class NativeIndexer { private: uint64_t allocate_version(); - void keep_lease() const; dmi_store::S3Client* s3_; CatalogWriter* writer_; diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index 483c4b9a3..8c928625e 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -83,7 +83,8 @@ class CaptureStorageService::LeaseScope { : service_(service), lock_(service->lease_mutex_), deadline_([service] { return service->writer_.lease_deadline_ns(); }, - kLeaseDeadlineBound) { + kLeaseDeadlineBound, + [service] { service->keep_lease_in_pass(); }) { service_->abandon_lease_if_expired(); } @@ -109,11 +110,7 @@ CaptureStorageService::CaptureStorageService(StorageServiceConfig config) s3_(config_.s3), clickhouse_(std::make_shared(config_.clickhouse)), writer_(clickhouse_, config_.writer), - indexer_(&s3_, &writer_, [this] { - IndexerConfig indexer = config_.indexer; - indexer.keep_lease = [this] { keep_lease_in_pass(); }; - return indexer; - }()) { + indexer_(&s3_, &writer_, config_.indexer) { if (config_.spool_root.empty()) { throw std::invalid_argument("storage service: spool_root is required"); } @@ -704,12 +701,12 @@ void CaptureStorageService::keep_lease() { // Renewing from the cycle let the lease lapse during an outage and a rival // take the catalog. This thread renews on its own schedule instead, and // takes a fresh lease once a lost one can be replaced. - const auto tick = - std::chrono::nanoseconds(lease_tick_ns(config_.writer.lease_ttl_ns)); + uint64_t wait_ns = lease_tick_ns(config_.writer.lease_ttl_ns); while (true) { { std::unique_lock lock(wake_mutex_); - wake_.wait_for(lock, tick, [this] { return lease_stop_requested_; }); + wake_.wait_for(lock, std::chrono::nanoseconds(wait_ns), + [this] { return lease_stop_requested_; }); if (lease_stop_requested_) return; } { @@ -717,12 +714,28 @@ void CaptureStorageService::keep_lease() { if (failure_) return; } LeaseScope lease(this); // publishes the lease state when done + // Wakes when the renewal falls due (a tick at most), not on a fixed + // tick: after a pass lets go of the lease lock, the renewal it leaves + // due has to start then, not up to a tick later. + const auto next_wake = [this] { + const uint64_t ttl = config_.writer.lease_ttl_ns; + const uint64_t tick = lease_tick_ns(ttl); + const uint64_t sent = writer_.lease_sent_ns(); + if (sent == 0) return tick; + const uint64_t due = sent + ttl / 3; + const uint64_t now = steady_ns(); + return std::clamp(due > now ? due - now : 0, 1'000'000ull, + tick); + }; if (writer_.held_lease() == nullptr) { ensure_publisher_lease(); + wait_ns = next_wake(); continue; } + wait_ns = lease_tick_ns(config_.writer.lease_ttl_ns); try { renew_lease_if_due(); + wait_ns = next_wake(); } catch (const CatalogError& exc) { if (is_lease_refusal(exc)) { // The coordinator dropped the lease: a live foreign head refused @@ -742,17 +755,20 @@ void CaptureStorageService::keep_lease() { void CaptureStorageService::renew_lease_if_due() { // Due a third of the TTL after the claim that stamped the lease row was - // sent -- this thread's last renewal, or the one a publish made before - // its fenced statements -- as the writer records it, so nothing but a - // confirmed claim moves the schedule. The lease thread looks every sixth - // of the TTL, so with the lease lock free a renewal starts within half the - // TTL of that send, and has until the lease deadline to be answered: the - // renewal window the constructor checks (lease_coordinator.h). A stretch - // under the lease lock delays it, but every request in such a stretch is - // bounded by the same deadline, and a pass renews through the indexer's - // keep_lease hook before each catalog write. A failed renewal costs the - // lease at once: a refusal drops it in the coordinator, and any other - // error quarantines the writer (renew_for_publish). + // sent -- the last renewal, or the one a publish made before its fenced + // statements -- as the writer records it, so nothing but a confirmed + // claim moves the schedule. The lease thread wakes when it falls due, and + // at least every sixth of the TTL, so with the lease lock free a renewal + // starts within half the TTL of that send (in practice at a third), and + // has until the lease deadline to be answered: the renewal window the + // constructor checks (lease_coordinator.h). While a stretch holds the + // lease lock, this runs before every request it sends (LeaseScope's + // before_request hook), reads included, so the lease is never more than + // a third of the TTL plus one request old when a renewal starts -- not + // several requests' worth, which a slow but healthy catalog could not fit + // a renewal after. A failed renewal costs the lease at once: a refusal + // drops it in the coordinator, and any other error quarantines the writer + // (renew_for_publish). const uint64_t ttl = config_.writer.lease_ttl_ns; const uint64_t sent = writer_.lease_sent_ns(); if (ttl == 0 || sent == 0 || steady_ns() - sent < ttl / 3) return; @@ -764,6 +780,7 @@ void CaptureStorageService::renew_lease_if_due() { } void CaptureStorageService::keep_lease_in_pass() { + // What it throws fails the request it ran for, and so the stretch. try { renew_lease_if_due(); } catch (const CatalogError&) { diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index cce9be764..f844191b6 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -44,10 +44,11 @@ // Bounded by the lease. Every catalog request the service makes while it // holds the lease -- the renewal's own, and every one an index pass or a // reconcile sends under the lease lock -- has to be answered by the lease -// deadline (lease_coordinator.h), since the lease cannot renew while that -// lock is held: so a catalog that stops answering fails the stretch, and the -// lease quarantines, while its row still keeps rivals out. A lease whose -// deadline passes unrenewed is abandoned, never reported held (LeaseScope). +// deadline (lease_coordinator.h), since while that lock is held the lease +// renews only between those requests, before each one that finds it due: +// so a catalog that stops answering fails the stretch, and the lease +// quarantines, while its row still keeps rivals out. A lease whose deadline +// passes unrenewed is abandoned, never reported held (LeaseScope). // An index pass reads its packs from the object store without the lock, so // a stalled read cannot hold the renewal off either. Claims made with no // lease are bounded by min(request timeout, lease_ttl / 3) per request; a @@ -221,9 +222,11 @@ class CaptureStorageService { // Holds lease_mutex_ for a stretch of catalog work, and bounds every // request the thread makes meanwhile by the held lease's deadline -- read // afresh per request, so a renewal inside the stretch extends it at once. - // A lease whose deadline has passed is abandoned on the way in and on the - // way out, so it is neither used nor reported held; the lease state is - // published on the way out. Every use of writer_'s lease goes through one. + // Before each request it renews the lease if that has fallen due + // (keep_lease_in_pass). A lease whose deadline has passed is abandoned on + // the way in and on the way out, so it is neither used nor reported held; + // the lease state is published on the way out. Every use of writer_'s + // lease goes through one. class LeaseScope; void loop(); @@ -240,7 +243,8 @@ class CaptureStorageService { void reconcile(); void keep_lease(); // the lease thread's body void renew_lease_if_due(); // requires lease_mutex_ - // The indexer's keep_lease hook: renew_lease_if_due() inside a pass. + // LeaseScope's before_request hook: renew_lease_if_due() before each + // request a stretch under the lease lock sends. void keep_lease_in_pass(); // requires lease_mutex_ // Gives up a held lease whose deadline has passed. Requires lease_mutex_. void abandon_lease_if_expired(); diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 1fd7c6a43..f31dfd742 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -279,10 +279,11 @@ class _Switch: """A TCP forwarder in front of an HTTP server -- ClickHouse's HTTP port, or the fake S3 -- that can be cut (connections refused), stalled (connections accepted, never answered), made to hold lease INSERTs back - and deliver them late, to stall only the requests a predicate picks, or - to hold the first request a predicate picks back for a while. Every - native client opens one connection per request, so one request is one - connection here.""" + and deliver them late, to stall only the requests a predicate picks, to + hold the first request a predicate picks back for a while, or to hold + every request back by a delay a function picks. Every native client + opens one connection per request, so one request is one connection + here.""" def __init__(self, host: str, port: int): self._target = (host, port) @@ -297,6 +298,9 @@ def __init__(self, host: str, port: int): # (predicate, seconds): the first matching request reaches the server # only that much later; its answer is relayed if anyone still listens. self._slow_once = None + # A function of one whole request: the seconds it reaches the + # server late (0 for at once); its answer is relayed as usual. + self._delay_by = None # time.monotonic() of every request stall_requests() held. self.stalled: list[float] = [] self._lock = threading.Lock() @@ -326,7 +330,8 @@ def _accept(self): client.close() continue if (self._late_by > 0 or self._stall_if is not None - or self._slow_once is not None): + or self._slow_once is not None + or self._delay_by is not None): threading.Thread(target=self._look_then_route, args=(client,), daemon=True).start() continue @@ -360,8 +365,8 @@ def _look_then_route(self, client): deliver_lease_inserts_late() reaches the server only after that delay -- long after the client gave up on it -- and nobody hears the answer; a request stall_requests() picks is never answered; the first - request slow_once() picks is forwarded late; anything else goes - straight through.""" + request slow_once() picks is forwarded late, and each request by + what delay_requests() says; anything else goes straight through.""" request = b"" continued = False try: @@ -402,6 +407,9 @@ def _look_then_route(self, client): if slow is not None and slow[0](request): self._slow_once = None time.sleep(slow[1]) + delay_by = self._delay_by + if delay_by is not None and (delay := delay_by(request)) > 0: + time.sleep(delay) late_by = self._late_by late = (late_by > 0 and b"INSERT INTO" in request and b"_publisher_lease" in request) @@ -442,6 +450,10 @@ def slow_once(self, predicate, seconds: float): """Forward the first request `predicate` picks `seconds` late.""" self._slow_once = (predicate, seconds) + def delay_requests(self, delay_by): + """Forward every request `delay_by(request_bytes)` seconds late.""" + self._delay_by = delay_by + def cut(self): self._up = False with self._lock: @@ -465,6 +477,7 @@ def restore(self): self._late_by = 0.0 self._stall_if = None self._slow_once = None + self._delay_by = None def close(self): self.cut() @@ -1549,6 +1562,66 @@ def _first_read(request: bytes) -> bool: assert sorted(captures) == sorted(tensors) +def _slow_catalog(insert_s: float, read_s: float): + """A delay_requests() function: a catalog slow but healthy, every INSERT + answered insert_s late and every SELECT read_s late.""" + def _delay(request: bytes) -> float: + body = request.partition(b"\r\n\r\n")[2] + if body.startswith(b"INSERT"): + return insert_s + if body.startswith(b"SELECT"): + return read_s + return 0.0 + return _delay + + +def test_a_slow_but_healthy_catalog_keeps_its_lease_through_index_passes( + fake_s3, tmp_path): + """Every request made under the lease lock has to be answered by the + lease deadline, and a pass renewed only at the indexer's keep_lease hook, + before its catalog writes. Between two hooks ran several requests with + no chance to renew -- allocate_version's two max() reads, its claim + INSERT and read-back; the publish's watermark INSERT, read-backs and the + inventory commit -- so against a catalog slow but healthy the renewal + at the next hook started with too little time left, timed out, and + quarantined the lease, pass after pass: flush() never drained. main + drained it, bounding nothing. The renewal is now checked before every + request made under the lease lock, reads included. Scaled 1/5: 0.6 s + INSERTs and 0.2 s reads against a 3 s TTL are 3 s and 1 s at the 15 s + default.""" + spool_root = tmp_path / "spool" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (client, catalog): + knobs = dict(reconcile_on_start=False, lease_ttl_s=3.0, + publish_timeout_s=1, clickhouse_request_timeout_s=20.0) + warm = _service(_storage_config(fake_s3, catalog.table_prefix, + **knobs), tmp_path / "warm") + warm.start() + warm.stop() + + switch.delay_requests(_slow_catalog(0.6, 0.2)) + service = _service(_storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + **knobs), spool_root) + service.start() + try: + tensors = _stage(spool_root, range(4)) # two packs + log = _sample_during(lambda: service.flush(60.0), service, + client, catalog.table_prefix, every=0.2) + snapshot = service.snapshot() + service.rethrow_if_failed() + finally: + switch.close() + service.stop() + + assert {state for _, state, _ in log} == {"held"}, log + assert not _held_but_dead(log), log + assert snapshot["indexed_packs"] == 2, snapshot + assert snapshot["lease_timeouts"] == 0, snapshot + captures = _read_all(_storage_config(fake_s3, catalog.table_prefix)) + assert sorted(captures) == sorted(tensors) + + def _lease_insert(request: bytes) -> bool: body = request.partition(b"\r\n\r\n")[2] return body.startswith(b"INSERT") and b"_publisher_lease` (term" in body From 4b1ef2321d79b4e30189d12243826800ac5dca32 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 11:42:49 -0400 Subject: [PATCH 07/13] Cap each lease INSERT attempt by the time it has, to the millisecond The lease INSERTs carry the time left before their deadline to the server as max_execution_time and lock_acquire_timeout, so the server abandons a claim when the client does. Two things made the cap wrong. The caps were computed once, before execute(), and execute() wrote them into a URL it built once, ahead of the retry loop. A lease INSERT whose first connections were refused -- retried, since nothing reached the server -- went out on a later attempt still claiming the time left before the first: with three attempts, about 0.3 s more than the client would wait. The URL is now built per attempt, and a per-attempt settings callback gives the coordinator the time each attempt has (the request timeout cut to the deadline in force) to cap it with. And the caps were whole seconds, rounded down: 4 s against the 5 s a default claim may take, 1 s against 1.999 s. The server aborted healthy INSERTs the client was still waiting for. They now go to the millisecond ("4.999"), which the server parses for both settings (checked on 25.12); a cap under a second already went out as a fraction. The driver-level tests put a forwarder in front of the fake catalog that stops listening after the head read is answered, so the INSERT goes out on its third attempt, and check that its cap ends by the client's deadline. A second test pins that an INSERT whose every attempt was refused wrote nothing, so the writer is not quarantined. --- native/csrc/catalog/clickhouse_client.cpp | 34 +++-- native/csrc/catalog/clickhouse_client.h | 14 +- native/csrc/catalog/lease_coordinator.cpp | 63 +++++---- native/csrc/catalog/lease_coordinator.h | 12 +- tests/test_native_capture_storage_live.py | 6 +- tests/test_native_lease_request_bound.py | 160 +++++++++++++++++++++- 6 files changed, 233 insertions(+), 56 deletions(-) diff --git a/native/csrc/catalog/clickhouse_client.cpp b/native/csrc/catalog/clickhouse_client.cpp index f48431ed6..ee833de61 100644 --- a/native/csrc/catalog/clickhouse_client.cpp +++ b/native/csrc/catalog/clickhouse_client.cpp @@ -462,7 +462,8 @@ ClickHouseClient::~ClickHouseClient() = default; std::vector ClickHouseClient::execute( const std::string& query, const Params& params, - const std::map& settings, int* attempts) const { + const std::map& settings, int* attempts, + const AttemptSettings& per_attempt) const { // First, so that what it does -- a lease renewal -- moves the deadline // before this request reads it. RequestDeadline::before_request(); @@ -471,15 +472,22 @@ std::vector ClickHouseClient::execute( // Settings ride as URL parameters; the statement is the POST body // (GET-with-query is evaluated as readonly — writes are refused). A - // caller's own wait_end_of_query wins over the default added here. - std::map url_settings = settings; - if (read) url_settings.emplace("wait_end_of_query", "1"); - std::string url = connection_.scheme + "://" + connection_.host + ":" + - std::to_string(connection_.port) + "/?"; - for (const auto& [key, value] : url_settings) { - url += url_encode(key) + "=" + url_encode(value) + "&"; - } - url.pop_back(); + // caller's own wait_end_of_query wins over the default added here. Built + // per attempt: per_attempt's settings depend on the time each one has. + const auto url_for = [&](long request_ms) { + std::map url_settings = settings; + if (per_attempt) { + per_attempt(static_cast(request_ms), &url_settings); + } + if (read) url_settings.emplace("wait_end_of_query", "1"); + std::string url = connection_.scheme + "://" + connection_.host + ":" + + std::to_string(connection_.port) + "/?"; + for (const auto& [key, value] : url_settings) { + url += url_encode(key) + "=" + url_encode(value) + "&"; + } + url.pop_back(); + return url; + }; // Credentials as headers: ClickHouse reads X-ClickHouse-User/-Key, and // unlike URL parameters or userinfo they do not end up in access logs or @@ -497,7 +505,8 @@ std::vector ClickHouseClient::execute( } } - const auto perform = [&](long connect_ms, long request_ms) { + const auto perform = [&](const std::string& url, long connect_ms, + long request_ms) { Attempt attempt; CURL* curl = curl_easy_init(); if (curl == nullptr) throw ClickHouseError("libcurl init failed"); @@ -576,7 +585,8 @@ std::vector ClickHouseClient::execute( connect_ms = std::min(connect_ms, request_ms); } - const Attempt attempt = perform(connect_ms, request_ms); + const Attempt attempt = + perform(url_for(request_ms), connect_ms, request_ms); if (attempt.code == CURLE_OK && attempt.status == 200) { if (attempts != nullptr) *attempts = number; return parse_tsv(attempt.body); diff --git a/native/csrc/catalog/clickhouse_client.h b/native/csrc/catalog/clickhouse_client.h index 668236e3d..bc9aa7da6 100644 --- a/native/csrc/catalog/clickhouse_client.h +++ b/native/csrc/catalog/clickhouse_client.h @@ -162,6 +162,13 @@ struct ClickHouseConnection { // contain the password. void validate(const ClickHouseConnection& connection); +// Settings computed for each attempt of a statement from the time that +// attempt is given -- the client's request timeout, cut to the +// RequestDeadline in force -- in whole milliseconds. See execute(). +using AttemptSettings = + std::function* settings)>; + // Whether a statement only reads, judged by its first keyword: SELECT, // SHOW, DESCRIBE/DESC, EXISTS, CHECK, or WITH when the word INSERT appears // nowhere in the statement (ClickHouse reads `WITH ... INSERT INTO ...` as @@ -222,10 +229,15 @@ class ClickHouseClient { // // `attempts`, when given, receives the number of requests the statement // took (1 without a retry); it is set only when execute() returns. + // + // `per_attempt`, when given, adds settings to each attempt from the time + // that attempt has, so that a server-side cap sent with a retry reflects + // the time left then, not before the first attempt (the lease INSERTs' + // max_execution_time, lease_coordinator.cpp). std::vector execute( const std::string& query, const Params& params = {}, const std::map& settings = {}, - int* attempts = nullptr) const; + int* attempts = nullptr, const AttemptSettings& per_attempt = {}) const; private: ClickHouseConnection connection_; diff --git a/native/csrc/catalog/lease_coordinator.cpp b/native/csrc/catalog/lease_coordinator.cpp index 41d79a560..093cb2e45 100644 --- a/native/csrc/catalog/lease_coordinator.cpp +++ b/native/csrc/catalog/lease_coordinator.cpp @@ -12,20 +12,22 @@ namespace { // How many recent claim lease_ids to remember (see claimed_ids_). constexpr size_t kClaimHistory = 16; -// A Seconds setting from whole milliseconds. Whole seconds wherever the -// value allows -- what every server parses, and what publish_timeout_ns -// already requires -- rounded DOWN, so the server's cap never exceeds the -// client's deadline. Only a time under a second goes out as a fraction, -// which current servers parse, for max_execution_time and -// lock_acquire_timeout alike (checked on 25.12). Never "0": ClickHouse reads -// a zero max_execution_time as no limit at all. +// A Seconds setting from whole milliseconds, to the millisecond ("1.999", +// "0.25", "4"): fractional seconds, which the server parses for +// max_execution_time and lock_acquire_timeout alike (checked on 25.12). +// Rounding down to whole seconds cut up to a second off an INSERT the +// client was still waiting for, so the server aborted healthy claims. +// Never "0": ClickHouse reads a zero max_execution_time as no limit at all. std::string seconds_setting(uint64_t ms) { - if (ms >= 1000) return std::to_string(ms / 1000); ms = std::max(ms, 1); - char out[8]; - std::snprintf(out, sizeof(out), "0.%03u", static_cast(ms)); - std::string text(out); - while (text.back() == '0') text.pop_back(); + std::string text = std::to_string(ms / 1000); + if (ms % 1000 != 0) { + char fraction[8]; + std::snprintf(fraction, sizeof(fraction), ".%03u", + static_cast(ms % 1000)); + text += fraction; + while (text.back() == '0') text.pop_back(); + } return text; } @@ -99,22 +101,27 @@ std::vector LeaseCoordinator::run( const RequestDeadline deadline( live ? lease_->deadline_ns : now + claim_bound_ns_, live ? std::string(kLeaseDeadlineBound) : claim_bound_text_); - if (write) add_write_caps(&settings); - return client_->execute(query, params, settings); + if (!write) return client_->execute(query, params, settings); + return client_->execute( + query, params, settings, nullptr, + [this](uint64_t attempt_ms, std::map* caps) { + add_write_caps(attempt_ms, caps); + }); } void LeaseCoordinator::add_write_caps( - std::map* settings) const { + uint64_t attempt_ms, std::map* settings) const { // A lease INSERT the client gave up on (a timeout, so an unknown outcome) // must not land afterwards: a claim row stamped then outlives the - // quarantine meant to cover it. So the server gets the time left before - // the request's deadline -- the tightest in force, as the client computes - // it -- and abandons the statement then: max_execution_time for running - // it, lock_acquire_timeout for waiting on the table lock before it starts, - // and throw, not break, since break would insert what had been read so - // far. The quorum wait is bounded by insert_quorum_timeout alone, so that - // is capped too, as well as by publish_timeout as before: past the - // deadline nobody is listening. + // quarantine meant to cover it. So the server gets the time the client + // gives the attempt -- its request timeout cut to the tightest deadline in + // force, computed afresh for every attempt, so a retry after a refused + // connection carries the time left then -- and abandons the statement + // then: max_execution_time for running it, lock_acquire_timeout for + // waiting on the table lock before it starts, and throw, not break, since + // break would insert what had been read so far. The quorum wait is bounded + // by insert_quorum_timeout alone, so that is capped too, as well as by + // publish_timeout as before: past the deadline nobody is listening. // // What the caps do not cover: ClickHouse checks max_execution_time only at // designated points while the pipeline runs, so the part commit can @@ -123,19 +130,15 @@ void LeaseCoordinator::add_write_caps( // up to that delay after the client gave up. The storage service // therefore does not count a refusal by its own claim rows towards its // 2 x TTL latch (refused_by_own_claims()). - const uint64_t deadline = RequestDeadline::current(); // run() set one - const uint64_t now = steady_now_ns(); - // 0 when the deadline has passed; execute() then sends nothing. - const uint64_t left_ms = deadline > now ? (deadline - now) / 1'000'000 : 0; if (config_.insert_quorum.has_value()) { (*settings)["insert_quorum"] = std::to_string(*config_.insert_quorum); (*settings)["insert_quorum_parallel"] = "0"; (*settings)["insert_quorum_timeout"] = std::to_string(std::max( - std::min(config_.publish_timeout_ns / 1'000'000, left_ms), + std::min(config_.publish_timeout_ns / 1'000'000, attempt_ms), 1)); } - (*settings)["max_execution_time"] = seconds_setting(left_ms); - (*settings)["lock_acquire_timeout"] = seconds_setting(left_ms); + (*settings)["max_execution_time"] = seconds_setting(attempt_ms); + (*settings)["lock_acquire_timeout"] = seconds_setting(attempt_ms); (*settings)["timeout_overflow_mode"] = "throw"; } diff --git a/native/csrc/catalog/lease_coordinator.h b/native/csrc/catalog/lease_coordinator.h index 5f9a025e2..1a3e7683c 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -54,9 +54,11 @@ namespace dmi_catalog { // fails well inside a TTL. So is a request made under a lease whose deadline // has already passed (run() says why it is still sent). // -// The lease INSERTs carry the time left before their deadline to the server -// as max_execution_time and lock_acquire_timeout, and cap a quorum wait by -// it, so the server abandons a claim no later than the client does. +// Each attempt of a lease INSERT carries the time the client gives it -- the +// time left before its deadline, recomputed for a retry -- to the server as +// max_execution_time and lock_acquire_timeout, to the millisecond, and caps +// a quorum wait by it, so the server abandons a claim when the client does +// (up to the time the request took to reach the server). constexpr uint64_t kLeaseDeadlineMarginNs = 100'000'000ull; // The deadline of a lease whose claim INSERT was sent at `sent_ns` (steady @@ -196,7 +198,9 @@ class LeaseCoordinator { std::vector run(const std::string& query, const Params& params, std::map settings, bool write) const; - void add_write_caps(std::map* settings) const; + // The server-side caps on a lease INSERT attempt given attempt_ms. + void add_write_caps(uint64_t attempt_ms, + std::map* settings) const; std::shared_ptr client_; LeaseConfig config_; diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index f31dfd742..fe2fa8ce9 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -1741,7 +1741,7 @@ def test_the_lease_statements_carry_a_server_side_cap(fake_s3, tmp_path): land its claim row later -- after the quarantine that was meant to outlive it had ended. The cap makes the server abandon the INSERT no later than the client does: the time left before the request's - deadline, rounded down, and lock_acquire_timeout the same.""" + deadline, to the millisecond, and lock_acquire_timeout the same.""" with _catalog() as (client, catalog): # The production knobs: a 15 s TTL. config = _storage_config(fake_s3, catalog.table_prefix, @@ -1769,11 +1769,11 @@ def test_the_lease_statements_carry_a_server_side_cap(fake_s3, tmp_path): if "now_ns + toUInt64" in query: # A claim with no lease held: min(clickhouse_request_timeout_s, # lease_ttl_s / 3) = 5 s, less the microseconds since. - assert cap == "4", (query, cap) + assert 4.9 < float(cap) <= 5.0, (query, cap) else: # A tombstone, under the lease: what is left of 15 s less # the 0.1 s margin since the claim was sent. - assert cap in ("13", "14"), (query, cap) + assert 12.0 < float(cap) < 14.9, (query, cap) assert lock == cap, (query, lock) # The log lists only settings that differ from the default, and # throw is the default; break would insert what had been read. diff --git a/tests/test_native_lease_request_bound.py b/tests/test_native_lease_request_bound.py index e5ed75c78..5550dafee 100644 --- a/tests/test_native_lease_request_bound.py +++ b/tests/test_native_lease_request_bound.py @@ -26,6 +26,7 @@ import json import os import re +import socket import subprocess import threading import time @@ -68,6 +69,11 @@ def __init__(self): # (statement prefix, seconds): answer every such statement that late, # with a 503 -- a failure the client retries for a read. self.unavailable: tuple[str, float] | None = None + # Called before the head read is answered, from the thread serving + # it. + self.before_head_answer = None + # When each statement arrived, by prefix of its body. + self.arrivals: list[tuple[float, str]] = [] self._released = threading.Event() self._claimed = "" fake = self @@ -79,6 +85,7 @@ def do_POST(self): # noqa: N802 -- the http.server hook name settings = {key: values[-1] for key, values in parse_qs(urlsplit(self.path).query).items()} fake.requests.append((settings, body)) + fake.arrivals.append((time.monotonic(), body)) if fake.stall is not None and body.startswith(fake.stall): fake._released.wait(30) return @@ -99,6 +106,8 @@ def do_POST(self): # noqa: N802 -- the http.server hook name answer = "" elif body.startswith(HEAD): answer = fake.head_rows + if fake.before_head_answer is not None: + fake.before_head_answer() elif body.startswith(READ_BACK): answer = f"{fake._claimed}\t1\t2\n" else: @@ -181,7 +190,8 @@ def test_the_lease_inserts_carry_the_time_left_as_a_server_cap( longer (lock_acquire_timeout), never later than the client's own deadline. A claim with no lease held has min(request timeout, TTL / 3); the tombstone, sent under the lease, what is left of the TTL less the - 0.1 s margin. Whole seconds rounded down, a fraction only under one.""" + 0.1 s margin. To the millisecond, rounded down: whole seconds cut up to + a second off a healthy INSERT the client would still have waited for.""" assert driver.open(lease_ttl_ns=ttl_ns, publish_timeout_ns=publish_ns)["ok"] claimed = driver.call(op="claim", holder="h", lease_id=str(uuid.uuid4())) assert claimed["ok"], claimed @@ -192,9 +202,7 @@ def test_the_lease_inserts_carry_the_time_left_as_a_server_cap( lease_left = ttl_ns / 1e9 - 0.1 for settings, bound in ((claim, claim_bound), (tombstone, lease_left)): cap = float(settings["max_execution_time"]) - assert 0 < cap < bound, settings - # Rounded down to whole seconds from one up: 9.99 s left sends "9". - assert cap >= bound - 1 if bound > 1 else cap > bound - 0.05, settings + assert bound - 0.05 < cap <= bound, settings assert settings["lock_acquire_timeout"] == \ settings["max_execution_time"], settings # break would insert whatever had been read by then. @@ -217,8 +225,8 @@ def test_a_quorum_lease_insert_waits_no_longer_than_its_deadline( claim, tombstone = fake.inserts() # No lease yet: TTL / 3 = 4 s left, less than the 5 s publish timeout. - assert 3900 < int(claim["insert_quorum_timeout"]) < 4000, claim - assert claim["max_execution_time"] == "3", claim + assert 3900 < int(claim["insert_quorum_timeout"]) <= 4000, claim + assert 3.9 < float(claim["max_execution_time"]) <= 4.0, claim assert claim["insert_quorum"] == "2", claim # Under the lease, nearly 12 s are left: publish_timeout caps it. assert tombstone["insert_quorum_timeout"] == "5000", tombstone @@ -388,6 +396,146 @@ def test_a_refusal_by_the_writers_own_claim_row_is_attributed_to_it( other.close() +class _Gate: + """A TCP forwarder in front of the fake that can stop listening for a + while, so that connections are refused -- a restarting catalog, or a + load balancer whose backend went away -- and then listen again on the + same port. One request is one connection for the native client.""" + + def __init__(self, target_port: int): + self._target = target_port + self.port = 0 + self._listener: socket.socket | None = None + self._lock = threading.Lock() + self._open() + + def _open(self): + listener = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + listener.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + listener.bind(("127.0.0.1", self.port)) + listener.listen(64) + self.port = listener.getsockname()[1] + with self._lock: + self._listener = listener + threading.Thread(target=self._accept, args=(listener,), + daemon=True).start() + + def _accept(self, listener): + while True: + try: + client, _ = listener.accept() + except OSError: + return + upstream = socket.create_connection(("127.0.0.1", self._target)) + for source, sink in ((client, upstream), (upstream, client)): + threading.Thread(target=self._pump, args=(source, sink), + daemon=True).start() + + @staticmethod + def _pump(source, sink): + try: + while True: + data = source.recv(65536) + if not data: + break + sink.sendall(data) + except OSError: + pass + finally: + for end in (source, sink): + try: + end.shutdown(socket.SHUT_RDWR) + except OSError: + pass + + def _stop(self): + with self._lock: + listener, self._listener = self._listener, None + if listener is not None: + # shutdown() first: a close() alone leaves the socket listening + # while the accept thread still blocks on it. + try: + listener.shutdown(socket.SHUT_RDWR) + except OSError: + pass + listener.close() + + def refuse_for(self, seconds: float): + """Stop listening now, and listen again `seconds` later.""" + self._stop() + timer = threading.Timer(seconds, self._open) + timer.daemon = True + timer.start() + + def close(self): + self._stop() + + +@pytest.fixture +def gate(fake): + forwarder = _Gate(fake.port) + yield forwarder + forwarder.close() + + +@pytest.fixture +def gated_driver(gate): + process = _Driver(gate.port) + yield process + process.close() + + +def test_a_lease_insert_retried_after_refused_connections_carries_the_time_then_left( + fake, gate, gated_driver): + """A lease INSERT whose connection is refused is retried, since nothing + reached the server. The caps rode in the URL built once, before the + first attempt, so the attempt that got through told the server it had + the time left before the first: the server could run the claim past + the client's deadline by the refused attempts and their backoff. Each + attempt now carries the time left when it goes out.""" + assert gated_driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + answered = [] + + def _refuse(): + answered.append(time.monotonic()) + gate.refuse_for(0.25) + + fake.before_head_answer = _refuse + claimed = gated_driver.call(op="claim", holder="h", + lease_id=str(uuid.uuid4())) + assert claimed["ok"], claimed + arrived, _ = next(arrival for arrival in fake.arrivals + if arrival[1].startswith("INSERT")) + (settings,) = fake.inserts() + # Refused at once, then 0.1 s and 0.2 s of backoff: the third attempt. + assert arrived - answered[0] > 0.25, (arrived, answered) + cap = float(settings["max_execution_time"]) + assert settings["lock_acquire_timeout"] == settings["max_execution_time"] + # The claim bound, 1 s at a 3 s TTL, counts from the INSERT's first + # attempt, just after the head read was answered. + assert arrived + cap <= answered[0] + 1.0 + 0.02, (arrived, cap, answered) + + +def test_a_lease_insert_that_never_connected_wrote_nothing( + fake, gate, gated_driver): + """A claim INSERT whose every attempt was refused its connection cannot + have reached the server: its outcome is known, so the writer is not + quarantined and may claim again at once.""" + assert gated_driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + fake.before_head_answer = lambda: gate.refuse_for(1.5) + refused = gated_driver.call(op="acquire", holder="h") + assert not refused["ok"], refused + assert refused["error"] == "ClickHouseError", refused + assert "connect" in refused["message"].lower(), refused + assert not fake.inserts(), fake.requests + fake.before_head_answer = None + time.sleep(1.6) + assert gated_driver.call(op="quarantined")["quarantined"] is False + assert gated_driver.call(op="acquire", holder="h")["ok"] + + # --- the storage service's configuration -------------------------------------- From 37b57280e808ae48dca613fb7d46cd89c2c2e6a8 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 11:45:22 -0400 Subject: [PATCH 08/13] Confirm a lease claim by the deadline of the lease it takes A claim made without a lease bounded each of its requests by the claim bound, min(request timeout, TTL / 3), from when that request started, so its read-back had a full bound of its own after the INSERT. The lease the claim takes has until sent + TTL - skew - 0.1 s. Once the clock skew is over TTL / 3 - 0.1 s -- which validation accepts, up to TTL / 2 - 0.3 s -- an INSERT and a read-back each inside the bound could confirm the claim after its own deadline. The service counted that as a success (a reacquisition, "held", the timeout streak reset), then abandoned the lease at once for "not renewed by the lease deadline". No timeout was counted and the knobs were never named, so against such a catalog it looped claim, abandon, quarantine without saying why. From its INSERT on, a claim now runs under the deadline of the lease it would take as well as under its own bound: the INSERT, a contested claim's rival row, the read-back and the head read after a claim not recorded. A claim that cannot be confirmed in time fails as a timeout naming lease_ttl_s and clock_skew_s, and, its INSERT sent, quarantines. On a renewal the old lease's deadline is earlier and still what binds. --- native/csrc/catalog/lease_coordinator.cpp | 14 ++++++-- native/csrc/catalog/lease_coordinator.h | 4 ++- tests/test_native_lease_request_bound.py | 41 +++++++++++++++++++++++ 3 files changed, 56 insertions(+), 3 deletions(-) diff --git a/native/csrc/catalog/lease_coordinator.cpp b/native/csrc/catalog/lease_coordinator.cpp index 093cb2e45..e7045a4be 100644 --- a/native/csrc/catalog/lease_coordinator.cpp +++ b/native/csrc/catalog/lease_coordinator.cpp @@ -217,6 +217,17 @@ PublisherLease LeaseCoordinator::claim_with_rival( // Taken before the INSERT goes out, so never after the server stamps the // row: the new lease's deadline counts from here. const uint64_t sent_ns = steady_now_ns(); + const uint64_t deadline_ns = + lease_deadline_ns(sent_ns, config_.lease_ttl_ns, config_.clock_skew_ns); + // The lease this claim takes is good only until deadline_ns, so the claim + // has to be confirmed by then: from its INSERT on, every request of it is + // bounded by that deadline as well as by its own (run()). A claim made + // without a lease otherwise gave its read-back a fresh claim bound, and + // with a clock skew over TTL / 3 - 0.1 s an INSERT and read-back each + // inside the bound could confirm a lease already past its deadline -- a + // success its holder had to abandon at once, with no timeout to say why. + // On a renewal the old lease's deadline, earlier still, is what binds. + const RequestDeadline confirmed_by(deadline_ns, kLeaseDeadlineBound); claim_insert_sent_ = true; try { insert(term, lease_id, holder); @@ -256,8 +267,7 @@ PublisherLease LeaseCoordinator::claim_with_rival( parse_u64_field(rows[0][1], "lease acquisition"), parse_u64_field(rows[0][2], "lease expiry"), sent_ns, - lease_deadline_ns(sent_ns, config_.lease_ttl_ns, - config_.clock_skew_ns)}; + deadline_ns}; return *lease_; } lease_.reset(); diff --git a/native/csrc/catalog/lease_coordinator.h b/native/csrc/catalog/lease_coordinator.h index 1a3e7683c..549c14dec 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -52,7 +52,9 @@ namespace dmi_catalog { // requests is bounded by min(the client's request timeout, lease_ttl_ns / // 3): long enough for a slow catalog, short enough that a claim which hangs // fails well inside a TTL. So is a request made under a lease whose deadline -// has already passed (run() says why it is still sent). +// has already passed (run() says why it is still sent). From its INSERT on, +// a claim is also bounded by the deadline of the lease it takes: a claim +// confirmed after that would hand its holder a lease it could not use. // // Each attempt of a lease INSERT carries the time the client gives it -- the // time left before its deadline, recomputed for a retry -- to the server as diff --git a/tests/test_native_lease_request_bound.py b/tests/test_native_lease_request_bound.py index 5550dafee..4740cfde7 100644 --- a/tests/test_native_lease_request_bound.py +++ b/tests/test_native_lease_request_bound.py @@ -66,6 +66,8 @@ def __init__(self): self.stall: str | None = None # a statement prefix to never answer # (statement prefix, seconds): answer the first such statement late. self.delay: tuple[str, float] | None = None + # statement prefix -> seconds: answer every such statement late. + self.delays: dict[str, float] = {} # (statement prefix, seconds): answer every such statement that late, # with a 503 -- a failure the client retries for a read. self.unavailable: tuple[str, float] | None = None @@ -93,6 +95,9 @@ def do_POST(self): # noqa: N802 -- the http.server hook name seconds = fake.delay[1] fake.delay = None time.sleep(seconds) + for prefix, seconds in list(fake.delays.items()): + if body.startswith(prefix): + time.sleep(seconds) unavailable = fake.unavailable if unavailable is not None and body.startswith(unavailable[0]): time.sleep(unavailable[1]) @@ -329,6 +334,42 @@ def test_a_claim_quarantines_only_once_its_insert_may_have_landed( assert driver.call(op="quarantined")["quarantined"] is quarantined +@pytest.mark.parametrize("op", ["claim", "acquire"]) +def test_a_claim_is_confirmed_by_the_deadline_of_the_lease_it_takes( + fake, driver, op): + """Each request of a claim made without a lease had the claim bound, + min(request timeout, TTL / 3), from when it started -- the read-back + after the INSERT another full one. The lease the claim takes has until + sent + TTL - skew - 0.1 s. With a skew over TTL / 3 - 0.1 s (which + validation accepts), an INSERT and read-back each inside the bound could + confirm the claim after its own deadline: a success the service then + abandoned at once, blaming a renewal that never happened, and no + timeout counted. The requests after the INSERT are bounded by that + deadline too, so such a claim fails as a timeout that names the knobs, + and -- its INSERT sent -- quarantines.""" + assert driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000, + clock_skew_ns=1_200_000_000)["ok"] + # 0.9 s each, inside the 1 s claim bound; 1.8 s together, past the + # 3 - 1.2 - 0.1 = 1.7 s the new lease has. + fake.delays = {"INSERT": 0.9, READ_BACK: 0.9} + fields = {"holder": "h"} + if op == "claim": + fields["lease_id"] = str(uuid.uuid4()) + response, _ = _timed(lambda: driver.call(op=op, **fields)) + arrived = next(at for at, body in fake.arrivals + if body.startswith("INSERT")) + assert not response["ok"], response + assert response["error"] == "ClickHouseError", response + assert "Timeout" in response["message"], response + for knob in ("lease_ttl_s", "clock_skew_s"): + assert knob in response["message"], response + # Given up at the lease deadline, 1.7 s after the INSERT went out. + assert 1.55 < time.monotonic() - arrived < 1.9 + if op == "acquire": + assert driver.call(op="quarantined")["quarantined"] is True + + def test_a_slow_but_healthy_head_read_does_not_fail_the_claim(fake, driver): """A head read with select_sequential_consistency on a loaded catalog can take seconds, which a fixed TTL / 12 per request -- 1.25 s at the From 7cacce80d8bca3c99213d545637461c99102cf53 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 11:50:30 -0400 Subject: [PATCH 09/13] Let start() get past a slow claim INSERT start() still failed when its claim INSERT, rather than its head read, was slow -- the case the claim bound was meant not to fail -- in two ways. The client timed out the INSERT. It may have landed, so the writer quarantined for a TTL, and start() waited that out only when it ended inside start_lease_wait_s. At the default wait, lease_ttl_s + publish_timeout_s + clock_skew_s, it never did once the INSERT had used its claim bound (TTL / 3, the publish timeout at the defaults), so start() threw "leaves no time to try again" at once. The quarantine is our own claim row's possible lifetime, the same thing the wait exists to outlast for a crashed predecessor. So start() now waits it out even past the wait, once, with time for a claim after it: at most about start_lease_wait_s + 2 x lease_ttl_s against a catalog that slow, and a second such timeout fails start() as before. (The design said to wait the quarantine out "when it fits"; at the defaults it never fits.) Or the server gave up first. The lease INSERTs carry the time the client gives them as max_execution_time, lock_acquire_timeout and insert_quorum_timeout, and ClickHouse answers a limit that ran out with TIMEOUT_EXCEEDED (a 408), DEADLOCK_AVOIDED or UNKNOWN_STATUS_OF_INSERT. execute() raised those as ordinary errors, so start() rethrew them, and the service's lease-timeout count never saw them: on a catalog slow at running the lease INSERT, the knobs were never named. They are now timeouts, never retried, with messages that say which limit and which bound; their outcome is as unknown as before, so a claim still quarantines. The conformance driver reports timed_out and sent for a ClickHouse error, for the driver-level test. --- native/csrc/catalog/clickhouse_client.cpp | 47 +++++++++++++---- native/csrc/catalog/clickhouse_client.h | 9 ++-- native/csrc/catalog/conformance_catalog.cpp | 3 +- native/csrc/catalog/storage_service.cpp | 32 +++++++++--- native/csrc/catalog/storage_service.h | 15 +++--- src/dmi/storage/native_capture.py | 5 +- tests/test_native_capture_storage_live.py | 58 +++++++++++++++++++++ tests/test_native_lease_request_bound.py | 43 +++++++++++++++ 8 files changed, 184 insertions(+), 28 deletions(-) diff --git a/native/csrc/catalog/clickhouse_client.cpp b/native/csrc/catalog/clickhouse_client.cpp index ee833de61..fc69d199b 100644 --- a/native/csrc/catalog/clickhouse_client.cpp +++ b/native/csrc/catalog/clickhouse_client.cpp @@ -98,6 +98,19 @@ bool transient_clickhouse_error(int code) { } } +// The ClickHouse errors that say the server gave up on a statement for a +// time limit the request set: TIMEOUT_EXCEEDED (159, max_execution_time; +// answered with a 408), DEADLOCK_AVOIDED (473, lock_acquire_timeout) and +// UNKNOWN_STATUS_OF_INSERT (319, insert_quorum_timeout -- which the server +// also answers when it lost its Keeper session mid-insert, an unknown +// outcome either way). The lease INSERTs set all three from the time the +// client gives them (lease_coordinator.cpp), so the server often gives up +// first: that is the request running out of time as surely as the client's +// own timeout, and execute() says so (ClickHouseError::timed_out). +bool server_time_limit(int code) { + return code == 159 || code == 473 || code == 319; +} + // libcurl takes whole milliseconds, and 0 means "its default" -- no bound at // all for the whole request. A positive timeout therefore rounds UP, so one // below a millisecond still bounds the request (at 1 ms); validate() has @@ -594,20 +607,24 @@ std::vector ClickHouseClient::execute( if (attempt.code == CURLE_OK || !never_connected(attempt.code)) { sent = true; } + // Named in a timeout's message, so whoever reads it knows which knob to + // turn: the deadline that cut the attempt short, or the client's own + // timeouts. + const auto bounded_by = [&] { + return by_deadline + ? " -- bounded by " + bound + : " -- bounded by the client's timeouts " + "(clickhouse_request_timeout_s = " + + seconds_text(connection_.timeouts.request_s) + + ", clickhouse_connect_timeout_s = " + + seconds_text(connection_.timeouts.connect_s) + ")"; + }; if (attempt.code == CURLE_OPERATION_TIMEDOUT) { - // Never retried (above). Named, so whoever reads it knows which knob - // to turn: the deadline that cut the attempt short, or the client's - // own timeouts. + // Never retried (above). std::string error = std::string("curl: ") + curl_easy_strerror(attempt.code); if (!attempt.detail.empty()) error += ": " + attempt.detail; - error += by_deadline - ? " -- bounded by " + bound - : " -- bounded by the client's timeouts " - "(clickhouse_request_timeout_s = " + - seconds_text(connection_.timeouts.request_s) + - ", clickhouse_connect_timeout_s = " + - seconds_text(connection_.timeouts.connect_s) + ")"; + error += bounded_by(); if (number > 1) { error += " (attempt " + std::to_string(number) + ")"; } @@ -629,6 +646,16 @@ std::vector ClickHouseClient::execute( // say, and is retried as before. Reads only, either way. int code = attempt.exception_code; if (code < 0) code = body_exception_code(attempt.body); + if (server_time_limit(code)) { + // A timeout too, and like one never retried. + error += " -- the server's own time limit (max_execution_time, " + "lock_acquire_timeout or insert_quorum_timeout) ran out" + + bounded_by(); + if (number > 1) { + error += " (attempt " + std::to_string(number) + ")"; + } + throw ClickHouseError(error, true, sent); + } retry = read && attempt.status >= 500 && attempt.status < 600 && (code < 0 || transient_clickhouse_error(code)); } diff --git a/native/csrc/catalog/clickhouse_client.h b/native/csrc/catalog/clickhouse_client.h index bc9aa7da6..3bc88beb8 100644 --- a/native/csrc/catalog/clickhouse_client.h +++ b/native/csrc/catalog/clickhouse_client.h @@ -34,7 +34,9 @@ class ClickHouseError : public std::runtime_error { // The request ran out of time: the client's request (or connect) timeout, // or the RequestDeadline in force, ended it, or that deadline had already - // passed before it could be sent. The message names the bound. + // passed before it could be sent, or the server gave up on it for a time + // limit the request set (max_execution_time, lock_acquire_timeout, + // insert_quorum_timeout). The message names the bound. bool timed_out() const { return timed_out_; } // Whether the statement may have reached the server. False only when it // cannot have: every attempt was refused its connection (or the name did @@ -207,8 +209,9 @@ class ClickHouseClient { // so a 5xx that names a ClickHouse error (X-ClickHouse-Exception-Code, // or a "Code: N." body) is retried only for the few transient codes // listed in the .cpp; a 5xx naming none (a proxy's 502/503/504) is. - // A timeout is never retried, so each attempt's bound is the whole - // call's: at most max_attempts request timeouts plus the backoff, and a + // A timeout is never retried -- the client's own, or a time limit the + // server enforced (see ClickHouseError::timed_out) -- so each attempt's + // bound is the whole call's: at most max_attempts request timeouts plus the backoff, and a // single request timeout for anything that timed out. TLS failures (an // untrusted or misnamed certificate) and 4xx answers are not retried. // Timeouts go to libcurl in whole milliseconds, rounded up, so a positive diff --git a/native/csrc/catalog/conformance_catalog.cpp b/native/csrc/catalog/conformance_catalog.cpp index cd7799379..842e88f35 100644 --- a/native/csrc/catalog/conformance_catalog.cpp +++ b/native/csrc/catalog/conformance_catalog.cpp @@ -1119,7 +1119,8 @@ std::string respond(const std::string& line, Session* session) { std::string message; escape_into(e.what(), &message); return prefix + "false,\"error\":\"ClickHouseError\",\"message\":" + - message + "}"; + message + ",\"timed_out\":" + (e.timed_out() ? "true" : "false") + + ",\"sent\":" + (e.sent() ? "true" : "false") + "}"; } catch (const std::exception& e) { std::string message; escape_into(e.what(), &message); diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index 8c928625e..1a824333d 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -840,9 +840,12 @@ void CaptureStorageService::acquire_lease_at_start() { // out here turns a restart inside that window into a short delay instead // of a failed start; a live publisher keeps renewing, so the wait ends in // the same refusal as before, naming the holder. - const uint64_t deadline = steady_ns() + config_.start_lease_wait_ns; + uint64_t deadline = steady_ns() + config_.start_lease_wait_ns; const uint64_t poll = std::clamp( config_.writer.lease_ttl_ns / 10, 50'000'000ull, 500'000'000ull); + // Whether the wait has already been stretched for a quarantine this + // start()'s own claim left (below): once only. + bool stretched = false; while (true) { try { writer_.acquire_lease(config_.holder); @@ -863,18 +866,33 @@ void CaptureStorageService::acquire_lease_at_start() { std::chrono::nanoseconds(std::min(poll, deadline - now))); } catch (const ClickHouseError& exc) { // A claim that timed out -- a cold catalog's first reads can outlast - // the claim bound -- is retried within the same wait. One that wrote - // nothing (its head read timed out) goes again at once; one whose - // INSERT may have landed quarantined the writer for a TTL, which is - // waited out when it ends inside the wait. Any other error fails - // start() as before. + // the claim bound, and so can a slow INSERT -- is retried within the + // same wait. One that wrote nothing (its head read timed out) goes + // again at once. One whose INSERT may have landed quarantined the + // writer for a TTL: its row, if it landed, is live that long, as a + // crashed predecessor's is. The wait is sized for one of those, and a + // claim that used its bound has spent enough of it that the + // quarantine always ended past it at the defaults; so the quarantine + // is waited out even then, once, with time for a claim after it (one + // the late row refuses until it expires, if it landed). Any other + // error fails start() as before. record_error(std::string("publisher lease claim at start failed: ") + exc.what()); note_lease_failure(exc); if (!exc.timed_out() || config_.start_lease_wait_ns == 0) throw; uint64_t resume = steady_ns(); uint64_t until = 0; - if (writer_.quarantined(&until)) resume = std::max(resume, until); + if (writer_.quarantined(&until)) { + resume = std::max(resume, until); + // A claim's three requests, each within the claim bound, and a poll + // for the late row to expire. + const uint64_t claim_ns = + 3 * writer_.leases().claim_bound_ns() + poll; + if (!stretched && until + claim_ns > deadline) { + stretched = true; + deadline = until + claim_ns; + } + } if (resume >= deadline) { throw ClickHouseError( "storage service: the publisher lease claim timed out, and " diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index f844191b6..74a350ca9 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -52,9 +52,9 @@ // An index pass reads its packs from the object store without the lock, so // a stalled read cannot hold the renewal off either. Claims made with no // lease are bounded by min(request timeout, lease_ttl / 3) per request; a -// claim that times out at start() is retried until start_lease_wait_ns ends, -// and lease requests that keep timing out say which knobs bound them -// (snapshot().lease_timeout_error). The constructor refuses a clock skew +// claim that times out at start() is retried until start_lease_wait_ns ends +// (or, once, until the quarantine it left is over), and lease requests that +// keep timing out say which knobs bound them (snapshot().lease_timeout_error). The constructor refuses a clock skew // that leaves a renewal too little time to finish. #pragma once @@ -116,7 +116,9 @@ struct StorageServiceConfig { // How long start() waits for another holder's lease to expire before it // fails with the lease held. A crashed predecessor's lease stays live for - // up to its TTL; 0 fails at once. + // up to its TTL; 0 fails at once. A claim of start()'s own that timed out + // is retried within it, and a quarantine that claim left is waited out + // even past it, once (acquire_lease_at_start). uint64_t start_lease_wait_ns = 0; // Sweep a crashed sink's stale .open files before anything writes to the @@ -187,8 +189,9 @@ class CaptureStorageService { // Ensure the catalog schema, take the publisher lease (waiting up to // start_lease_wait_ns for another holder's to expire, or for a claim that - // timed out to go through), sweep the spool, reconcile once, then start - // the background cycle. The lease renews from the moment it is taken. + // timed out to go through -- past it, once, to wait out the quarantine + // such a claim left), sweep the spool, reconcile once, then start the + // background cycle. The lease renews from the moment it is taken. // Throws if the lease is still held by another publisher when the wait // ends, or its claim still times out. A lease lost while the reconcile // runs does not fail start(): the loop takes a fresh one, as it would diff --git a/src/dmi/storage/native_capture.py b/src/dmi/storage/native_capture.py index 57857db17..ebd9f76c4 100644 --- a/src/dmi/storage/native_capture.py +++ b/src/dmi/storage/native_capture.py @@ -589,7 +589,10 @@ def start(self) -> None: Waits up to ``start_lease_wait_s`` for another holder's lease to expire, then raises naming the holder. A claim that times out is - retried within the same wait. + retried within the same wait; one whose INSERT may have landed sets + the lease aside for ``lease_ttl_s``, and that is waited out even + past the wait, once, so start() can take up to about + ``start_lease_wait_s + 2 * lease_ttl_s`` against a catalog that slow. """ self._service.start() diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index fe2fa8ce9..89bd464d1 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -1424,6 +1424,64 @@ def test_start_survives_a_first_lease_read_slower_than_its_bound( switch.close() +def _first(predicate): + """A predicate that picks only the first request `predicate` does.""" + picked = [] + + def _pick(request: bytes) -> bool: + if picked or not predicate(request): + return False + picked.append(time.monotonic()) + return True + + return _pick + + +@pytest.mark.parametrize("delivered", [False, True], + ids=["never-delivered", "delivered-late"]) +def test_start_waits_out_the_quarantine_its_own_claim_left( + fake_s3, tmp_path, delivered): + """A claim INSERT that timed out at start() may still land, so it + quarantines the writer for a TTL -- and start() failed at once whenever + that quarantine ended past start_lease_wait_s, which at the default wait + (lease_ttl_s + publish_timeout_s + clock_skew_s) it always did once the + INSERT had used its claim bound: a slow INSERT at start, a cold + replicated catalog's quorum INSERT say, still failed start(). The + quarantine is now waited out even past the wait, once, like the live + row of a crashed predecessor it may be, and the claim made again after + it -- refused by the late row, if it landed, until that expires.""" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + knobs = dict(reconcile_on_start=False, lease_ttl_s=3.0, + publish_timeout_s=1) + warm = _service(_storage_config(fake_s3, catalog.table_prefix, + **knobs), tmp_path / "warm") + warm.start() + warm.stop() + + if delivered: + # Reaches the server after the 1 s claim bound: the row lands, + # and is this service's own, live for a TTL. + switch.slow_once(_lease_insert, 1.5) + else: + switch.stall_requests(_first(_lease_insert)) + service = _service(_storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + **knobs), tmp_path / "spool") + started = time.monotonic() + service.start() + try: + elapsed = time.monotonic() - started + snapshot = service.snapshot() + assert snapshot["lease_state"] == "held", snapshot + # The claim timed out at 1 s and quarantined until 4 s; the + # default wait, 3 + 1 = 4 s, ended before a claim could follow. + assert 3.9 < elapsed < 7.0, elapsed + finally: + service.stop() + switch.close() + + def _listing(request: bytes) -> bool: line = request.partition(b"\r\n")[0] return line.startswith(b"GET ") and b"list-type=2" in line diff --git a/tests/test_native_lease_request_bound.py b/tests/test_native_lease_request_bound.py index 4740cfde7..92370b364 100644 --- a/tests/test_native_lease_request_bound.py +++ b/tests/test_native_lease_request_bound.py @@ -71,6 +71,9 @@ def __init__(self): # (statement prefix, seconds): answer every such statement that late, # with a 503 -- a failure the client retries for a read. self.unavailable: tuple[str, float] | None = None + # (statement prefix, HTTP status, ClickHouse error code): answer + # every such statement with that error, as the server does. + self.fail: tuple[str, int, int] | None = None # Called before the head read is answered, from the thread serving # it. self.before_head_answer = None @@ -98,6 +101,17 @@ def do_POST(self): # noqa: N802 -- the http.server hook name for prefix, seconds in list(fake.delays.items()): if body.startswith(prefix): time.sleep(seconds) + failing = fake.fail + if failing is not None and body.startswith(failing[0]): + payload = (f"Code: {failing[2]}. DB::Exception: scripted " + "failure. (SCRIPTED)\n").encode() + self.send_response(failing[1]) + self.send_header("X-ClickHouse-Exception-Code", + str(failing[2])) + self.send_header("Content-Length", str(len(payload))) + self.end_headers() + self.wfile.write(payload) + return unavailable = fake.unavailable if unavailable is not None and body.startswith(unavailable[0]): time.sleep(unavailable[1]) @@ -370,6 +384,35 @@ def test_a_claim_is_confirmed_by_the_deadline_of_the_lease_it_takes( assert driver.call(op="quarantined")["quarantined"] is True +@pytest.mark.parametrize("status, code, timed_out", [ + (408, 159, True), # TIMEOUT_EXCEEDED: max_execution_time ran out + (500, 473, True), # DEADLOCK_AVOIDED: lock_acquire_timeout ran out + (500, 319, True), # UNKNOWN_STATUS_OF_INSERT: the quorum wait ran out + (500, 241, False), # MEMORY_LIMIT_EXCEEDED: not a time limit +]) +def test_a_lease_insert_the_server_gave_up_on_in_time_is_a_timeout( + fake, driver, status, code, timed_out): + """The lease INSERTs carry the time the client gives them as the + server's own limits, so a slow claim is often cut by the server first. + That came back as an ordinary error: start() did not retry it as it + retries a claim that timed out, and the service's lease-timeout count + never saw it, so the knobs to turn were never named. A time limit the + server enforced is now a timeout like the client's own; its outcome is + as unknown, so the claim still quarantines.""" + assert driver.open(lease_ttl_ns=3_000_000_000, + publish_timeout_ns=1_000_000_000)["ok"] + fake.fail = ("INSERT", status, code) + response = driver.call(op="acquire", holder="h") + assert not response["ok"], response + assert response["error"] == "ClickHouseError", response + assert response["timed_out"] is timed_out, response + assert response["sent"] is True, response + assert f"Code: {code}" in response["message"], response + if timed_out: + assert "lease_ttl_s / 3" in response["message"], response + assert driver.call(op="quarantined")["quarantined"] is True + + def test_a_slow_but_healthy_head_read_does_not_fail_the_claim(fake, driver): """A head read with select_sequential_consistency on a loaded catalog can take seconds, which a fixed TTL / 12 per request -- 1.25 s at the From e1dcef189f810b5eed1bf6eaa9e17e0270316d77 Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 11:53:02 -0400 Subject: [PATCH 10/13] Retry a schema install claim that timed out On a fresh catalog the first lease request start() makes is not its own claim but CatalogSchema::ensure()'s install-lease claim, on the same coordinator. Each request of that claim now has the claim bound, min(clickhouse_request_timeout_s, lease_ttl_s / 3) -- 5 s at the defaults, where main gave it the 60 s request timeout -- and take_the_install_lease caught only a refusal, so a cold server's first lease read failed start(). The first start against a new catalog is exactly when the server is likeliest to be cold, and the retry start() now makes for its own claim never ran, since ensure() had already thrown. A timed-out install claim is now retried within the install lease's existing budget (lease_ttl_s + 5 s), counted in time rather than in attempts since one attempt can take a TTL. It is not quarantined, as it was not before: an INSERT of it that lands late refuses the next claim until it expires, which the refusal branch already waits out. The slow-first-read start() test pre-warmed the schema so that the service's own claim was the first lease read, and never exercised this; it now runs against a fresh catalog too. The service header said every use of the writer's lease goes through a LeaseScope. ensure()'s install lease does not, before and after this change; the comment now says so. --- native/csrc/catalog/schema.cpp | 16 ++++++++++-- native/csrc/catalog/storage_service.h | 15 ++++++++--- tests/test_native_capture_storage_live.py | 31 +++++++++++++++-------- 3 files changed, 45 insertions(+), 17 deletions(-) diff --git a/native/csrc/catalog/schema.cpp b/native/csrc/catalog/schema.cpp index 9c9fae5b5..73789445f 100644 --- a/native/csrc/catalog/schema.cpp +++ b/native/csrc/catalog/schema.cpp @@ -604,10 +604,22 @@ bool CatalogSchema::take_the_install_lease(LeaseCoordinator* leases, static_cast(leases->ttl_ns()) / 1e9 + kInstallLeaseMarginS; const int attempts = std::max(1, static_cast(std::ceil(budget_s / kInstallLeaseRetryS))); - for (int attempt = 0; attempt < attempts; ++attempt) { + const uint64_t give_up_ns = + steady_now_ns() + static_cast(budget_s * 1e9); + for (int attempt = 0; attempt < attempts;) { try { leases->acquire("ensure_schema"); return true; + } catch (const ClickHouseError& e) { + // A claim that timed out: each of its requests has min(request + // timeout, TTL / 3), and a fresh catalog's first start -- when the + // server is likeliest to be cold -- can outlast that. Retried within + // the same budget, in time rather than attempts, since one attempt + // can take a TTL. One whose INSERT may have landed can be refused by + // that row when it does: the refusal branch below waits it out. + if (!e.timed_out() || steady_now_ns() >= give_up_ns) throw; + std::this_thread::sleep_for(std::chrono::nanoseconds(retry_sleep_ns)); + continue; } catch (const CatalogError& e) { if (e.kind() != CatalogError::Kind::kHeld) throw; if (verify_compatibility() == "complete") { @@ -617,7 +629,7 @@ bool CatalogSchema::take_the_install_lease(LeaseCoordinator* leases, stamp(); return false; } - if (attempt + 1 == attempts) throw; + if (++attempt == attempts) throw; std::this_thread::sleep_for( std::chrono::nanoseconds(retry_sleep_ns)); } diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index 74a350ca9..e1ec7cb4d 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -229,7 +229,13 @@ class CaptureStorageService { // (keep_lease_in_pass). A lease whose deadline has passed is abandoned on // the way in and on the way out, so it is neither used nor reported held; // the lease state is published on the way out. Every use of writer_'s - // lease goes through one. + // lease goes through one but the schema install's at start(), before + // anything else can use the coordinator: CatalogSchema::ensure() claims, + // renews and releases its install lease there directly, its DDL bounded + // by the client's timeouts rather than by that lease's deadline, and an + // install claim that timed out is retried, not quarantined -- a row of it + // that lands late refuses start()'s own claim until it expires, which + // start() waits out like any holder's. class LeaseScope; void loop(); @@ -285,9 +291,10 @@ class CaptureStorageService { // is not thread-safe. Timed, so flush() can give up at its deadline while // a cycle is still in flight. std::timed_mutex cycle_mutex_; - // Serialises every use of writer_'s lease: the lease thread renews it - // while cycles publish. Taken inside cycle_mutex_, never the other way, - // and only through a LeaseScope. + // Serialises every use of writer_'s lease (but the schema install's at + // start(), see LeaseScope): the lease thread renews it while cycles + // publish. Taken inside cycle_mutex_, never the other way, and only + // through a LeaseScope. std::mutex lease_mutex_; // Lease claims and renewals timed out since the last that succeeded. // Guarded by lease_mutex_. diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 89bd464d1..95cebf80f 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -1387,24 +1387,30 @@ def _lease_head_read(request: bytes) -> bool: return b"SELECT term, toString(lease_id)" in request +@pytest.mark.parametrize("schema", ["installed", "fresh"]) def test_start_survives_a_first_lease_read_slower_than_its_bound( - fake_s3, tmp_path): + fake_s3, tmp_path, schema): """A claim made without a lease has min(clickhouse_request_timeout_s, lease_ttl_s / 3) per request, and a cold server's first read can take longer. start() failed outright when its claim timed out; it now retries one that did, as it retries one another holder refused, until start_lease_wait_s runs out. A head read that timed out wrote nothing, - so it does not quarantine the writer and the retry need not wait.""" + so it does not quarantine the writer and the retry need not wait. On a + fresh catalog the first lease read is the schema install's claim, and + that is the first start against a new catalog -- when the server is + likeliest to be cold -- so it is retried the same way, within the + install lease's own wait.""" switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) with _catalog() as (_client, catalog): knobs = dict(reconcile_on_start=False, lease_ttl_s=3.0, publish_timeout_s=1) - # The schema first, directly: then the service's own claim is the - # first lease read through the switch. - warm = _service(_storage_config(fake_s3, catalog.table_prefix, - **knobs), tmp_path / "warm") - warm.start() - warm.stop() + if schema == "installed": + # The schema first, directly: then the service's own claim is + # the first lease read through the switch. + warm = _service(_storage_config(fake_s3, catalog.table_prefix, + **knobs), tmp_path / "warm") + warm.start() + warm.stop() switch.slow_once(_lease_head_read, 1.5) # past the 1 s claim bound service = _service(_storage_config( @@ -1416,9 +1422,12 @@ def test_start_survives_a_first_lease_read_slower_than_its_bound( elapsed = time.monotonic() - started snapshot = service.snapshot() assert snapshot["lease_state"] == "held", snapshot - # Retried at once, without waiting out a 3 s quarantine. - assert 1.0 <= elapsed < 2.5, elapsed - assert "Timeout" in snapshot["last_error"], snapshot + # Retried at once (the install claim after its 0.5 s retry + # sleep), without waiting out a 3 s quarantine. + assert 1.0 <= elapsed < 3.0, elapsed + if schema == "installed": + # The schema install records no error of its own. + assert "Timeout" in snapshot["last_error"], snapshot finally: service.stop() switch.close() From 7521ecb55cd24c6e846bc8e8cc662749cff28f0a Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 12:04:46 -0400 Subject: [PATCH 11/13] Count every timeout that costs the publisher lease The lease-timeout streak, which names lease_ttl_s, clock_skew_s and clickhouse_request_timeout_s once it reaches three, reset on every claim that succeeded and counted only claims and renewals that timed out. Against a catalog too slow to keep a lease the service goes round: a claim goes through, then a renewal or a request of the index pass runs out of lease, the writer quarantines, and the next claim goes through again. The count went 1, 0, 1, 0, and the knobs were never named. A renewal inside publish_snapshot, a pass request the lease deadline cut off, and a lease abandoned at its deadline were never counted at all. Every timeout that costs the lease now counts once: - a claim or renewal that timed out, as before, the server's own time limit included; - a lease abandoned at its deadline; - any stretch under the lease lock that lost its lease to a request that timed out, which LeaseScope sees on its way out. The client records, in each RequestDeadline scope, whether the last request made under it timed out; a loss already counted inside the stretch is not counted again. The count clears only once a lease has been held for 2 x TTL, as seen at the end of a stretch under the lease lock -- not when a claim or a renewal succeeds. (The design said "resets on a successful renewal"; against the catalog in the test the lease renews several times before a pass request runs it out, so that would still hide the loop.) The live test runs a service against a catalog answering INSERTs 0.9 s and reads 0.4 s late at a 3 s TTL: claims go through and the lease is lost after each, and the snapshot now names the knobs within about 15 s. --- native/csrc/catalog/clickhouse_client.cpp | 27 ++++++++- native/csrc/catalog/clickhouse_client.h | 7 +++ native/csrc/catalog/storage_service.cpp | 64 +++++++++++++++++---- native/csrc/catalog/storage_service.h | 33 +++++++---- tests/test_native_capture_storage_live.py | 69 ++++++++++++++++++++++- 5 files changed, 175 insertions(+), 25 deletions(-) diff --git a/native/csrc/catalog/clickhouse_client.cpp b/native/csrc/catalog/clickhouse_client.cpp index fc69d199b..473c9e5ad 100644 --- a/native/csrc/catalog/clickhouse_client.cpp +++ b/native/csrc/catalog/clickhouse_client.cpp @@ -283,6 +283,13 @@ uint64_t RequestDeadline::current(std::string* bound) { return tightest; } +void RequestDeadline::note_outcome(const std::string& timeout) { + for (RequestDeadline* scope = innermost_deadline; scope != nullptr; + scope = scope->outer_) { + scope->last_timeout_ = timeout; + } +} + void RequestDeadline::before_request() { const RequestDeadline* scope = innermost_deadline; if (scope == nullptr || !scope->before_request_ || in_before_request) { @@ -480,6 +487,20 @@ std::vector ClickHouseClient::execute( // First, so that what it does -- a lease renewal -- moves the deadline // before this request reads it. RequestDeadline::before_request(); + // The outcome every scope in force records (RequestDeadline::last_timeout): + // a timeout's message, noted where one is thrown, or empty however else + // this call ends. + struct Outcome { + bool noted = false; + ~Outcome() { + if (!noted) RequestDeadline::note_outcome(""); + } + } outcome; + const auto timed_out = [&outcome](const std::string& error, bool sent) { + RequestDeadline::note_outcome(error); + outcome.noted = true; + return ClickHouseError(error, true, sent); + }; const std::string statement = substitute(query, params); const bool read = is_read_statement(statement); @@ -589,7 +610,7 @@ std::vector ClickHouseClient::execute( if (number > 1) { error += "; the attempt before failed with: " + last_error; } - throw ClickHouseError(error, true, sent); + throw timed_out(error, sent); } if (left_ms < static_cast(request_ms)) { request_ms = static_cast(left_ms); @@ -628,7 +649,7 @@ std::vector ClickHouseClient::execute( if (number > 1) { error += " (attempt " + std::to_string(number) + ")"; } - throw ClickHouseError(error, true, sent); + throw timed_out(error, sent); } std::string error; bool retry = false; @@ -654,7 +675,7 @@ std::vector ClickHouseClient::execute( if (number > 1) { error += " (attempt " + std::to_string(number) + ")"; } - throw ClickHouseError(error, true, sent); + throw timed_out(error, sent); } retry = read && attempt.status >= 500 && attempt.status < 600 && (code < 0 || transient_clickhouse_error(code)); diff --git a/native/csrc/catalog/clickhouse_client.h b/native/csrc/catalog/clickhouse_client.h index 3bc88beb8..8b449dfd7 100644 --- a/native/csrc/catalog/clickhouse_client.h +++ b/native/csrc/catalog/clickhouse_client.h @@ -92,11 +92,18 @@ class RequestDeadline { // not already running. What the hook throws propagates. static void before_request(); + // What the last request made on this thread while the scope lived (in a + // nested scope too) timed out with; empty if it did not time out, or if + // none was made. execute() records it, by note_outcome(). + const std::string& last_timeout() const { return last_timeout_; } + static void note_outcome(const std::string& timeout); + private: uint64_t fixed_ns_ = 0; std::function moving_ns_; std::string bound_; std::function before_request_; + std::string last_timeout_; RequestDeadline* outer_; }; diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index 1a824333d..b27b23a6b 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -86,11 +86,25 @@ class CaptureStorageService::LeaseScope { kLeaseDeadlineBound, [service] { service->keep_lease_in_pass(); }) { service_->abandon_lease_if_expired(); + const PublisherLease* held = service_->writer_.held_lease(); + if (held != nullptr) held_on_entry_ = held->lease_id; + counted_on_entry_ = service_->lease_timeouts_counted_; } ~LeaseScope() { try { service_->abandon_lease_if_expired(); + // A lease this stretch lost to a request that timed out -- one its + // deadline cut off, or the server's own time limit -- counts towards + // lease_timeouts, unless what lost it counted already (a renewal or + // claim that timed out, or the abandon above). + const PublisherLease* held = service_->writer_.held_lease(); + const bool lost = !held_on_entry_.empty() && + (held == nullptr || held->lease_id != held_on_entry_); + if (lost && service_->lease_timeouts_counted_ == counted_on_entry_ && + !deadline_.last_timeout().empty()) { + service_->count_lease_timeout(deadline_.last_timeout()); + } service_->publish_lease_state(); } catch (...) { } @@ -103,6 +117,8 @@ class CaptureStorageService::LeaseScope { CaptureStorageService* service_; std::unique_lock lock_; RequestDeadline deadline_; // after lock_: released before it + std::string held_on_entry_; // the lease_id held on entry, "" for none + uint64_t counted_on_entry_ = 0; }; CaptureStorageService::CaptureStorageService(StorageServiceConfig config) @@ -774,7 +790,6 @@ void CaptureStorageService::renew_lease_if_due() { if (ttl == 0 || sent == 0 || steady_ns() - sent < ttl / 3) return; writer_.renew_lease(); held_elsewhere_since_ns_ = 0; - note_lease_success(); std::lock_guard lock(state_mutex_); ++state_.lease_renewals; } @@ -796,23 +811,30 @@ void CaptureStorageService::abandon_lease_if_expired() { const uint64_t deadline = writer_.lease_deadline_ns(); if (deadline == 0 || steady_ns() < deadline) return; writer_.abandon_lease(); - record_error(std::string("publisher lease abandoned: it was not renewed " - "by ") + kLeaseDeadlineBound); + const std::string message = + std::string("publisher lease abandoned: it was not renewed by ") + + kLeaseDeadlineBound; + record_error(message); + count_lease_timeout(message); } void CaptureStorageService::note_lease_failure(const std::exception& failure) { const auto* error = dynamic_cast(&failure); - if (error == nullptr || !error->timed_out()) return; + if (error != nullptr && error->timed_out()) count_lease_timeout(error->what()); +} + +void CaptureStorageService::count_lease_timeout(const std::string& latest) { ++lease_timeouts_; + ++lease_timeouts_counted_; std::string message; if (lease_timeouts_ >= 3) { // The knobs first: last_error keeps only its first 512 bytes. const uint64_t claim_bound = writer_.leases().claim_bound_ns(); message = std::to_string(lease_timeouts_) + - " publisher lease claims or renewals have timed out since one last " - "succeeded. Requests made under the lease have until its deadline, " - "lease_ttl_s (" + + " timeouts have cost the publisher lease since one was last held " + "for 2 x lease_ttl_s. Requests made under the lease have until its " + "deadline, lease_ttl_s (" + seconds_text(config_.writer.lease_ttl_ns) + ") less clock_skew_s (" + seconds_text(config_.writer.clock_skew_ns) + ") and a " + seconds_text(kLeaseDeadlineMarginNs) + @@ -820,7 +842,7 @@ void CaptureStorageService::note_lease_failure(const std::exception& failure) { "of a claim made without one has min(clickhouse_request_timeout_s, " "lease_ttl_s / 3) = " + seconds_text(claim_bound) + ". A catalog this slow needs a longer lease_ttl_s. The latest: " + - error->what(); + latest; record_error(message); } std::lock_guard lock(state_mutex_); @@ -828,7 +850,28 @@ void CaptureStorageService::note_lease_failure(const std::exception& failure) { state_.lease_timeout_error = message.substr(0, 1024); } -void CaptureStorageService::note_lease_success() { +void CaptureStorageService::track_stable_lease() { + // Not on every claim or renewal that succeeds: against a catalog too slow + // to keep a lease, each claim goes through and the lease is then lost to + // a timeout, and a count cleared by the claim never got past one. A lease + // held for 2 x TTL -- renewed through several deadlines -- is one the + // catalog can keep. A lease_id names one holding: every claim after a + // loss mints a fresh one, and renewals keep it. + const PublisherLease* held = writer_.held_lease(); + if (held == nullptr) { + stable_lease_id_.clear(); + return; + } + const uint64_t now = steady_ns(); + if (held->lease_id != stable_lease_id_) { + stable_lease_id_ = held->lease_id; + stable_since_ns_ = now; + return; + } + if (lease_timeouts_ == 0 || + now - stable_since_ns_ < 2 * config_.writer.lease_ttl_ns) { + return; + } lease_timeouts_ = 0; std::lock_guard lock(state_mutex_); state_.lease_timeouts = 0; @@ -849,7 +892,6 @@ void CaptureStorageService::acquire_lease_at_start() { while (true) { try { writer_.acquire_lease(config_.holder); - note_lease_success(); return; } catch (const CatalogError& exc) { if (!is_lease_refusal(exc) || config_.start_lease_wait_ns == 0) throw; @@ -952,7 +994,6 @@ bool CaptureStorageService::ensure_publisher_lease() { publish_lease_state(); return false; } - note_lease_success(); held_elsewhere_since_ns_ = 0; next_claim_ns_ = 0; { @@ -1004,6 +1045,7 @@ void CaptureStorageService::lease_held_elsewhere(const CatalogError& refusal) { } void CaptureStorageService::publish_lease_state() { + track_stable_lease(); uint64_t until = 0; const char* lease_state = "reacquiring"; if (writer_.held_lease() != nullptr) { diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index e1ec7cb4d..a088ff0cc 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -171,10 +171,13 @@ struct StorageServiceSnapshot { // steady_clock ns at which the quarantine ends; 0 when not quarantined. uint64_t quarantined_until_ns = 0; uint64_t lease_reacquisitions = 0; // fresh leases taken after a loss - // Lease claims and renewals that timed out since one last succeeded. - // From the third on, lease_timeout_error says so and names the knobs that - // bound them (it is last_error too, when it happens); both clear once a - // claim or renewal succeeds. + // Timeouts that cost the publisher lease -- a claim or renewal that timed + // out (the server's own time limit included), a request made under the + // lease that its deadline cut off, a lease abandoned at its deadline -- + // since a lease was last held for 2 x TTL. From the third on, + // lease_timeout_error says so and names the knobs that bound them (it is + // last_error too, when it happens); both clear once a lease has been held + // for 2 x TTL again. uint64_t lease_timeouts = 0; std::string lease_timeout_error; std::string last_error; @@ -255,14 +258,18 @@ class CaptureStorageService { // LeaseScope's before_request hook: renew_lease_if_due() before each // request a stretch under the lease lock sends. void keep_lease_in_pass(); // requires lease_mutex_ - // Gives up a held lease whose deadline has passed. Requires lease_mutex_. + // Gives up a held lease whose deadline has passed, counting it towards + // lease_timeouts. Requires lease_mutex_. void abandon_lease_if_expired(); // A lease claim or renewal failed (call from its catch block): one that // timed out counts towards lease_timeouts. Requires lease_mutex_. void note_lease_failure(const std::exception& failure); - // A claim or renewal succeeded: clears the timeout count. Requires - // lease_mutex_. - void note_lease_success(); + // Counts one timeout that cost the lease; `latest` says what it was. + // Requires lease_mutex_. + void count_lease_timeout(const std::string& latest); + // Clears the timeout count once the lease now held has been held for + // 2 x TTL (publish_lease_state runs it). Requires lease_mutex_. + void track_stable_lease(); // Takes the lease at start(), waiting for an expiring predecessor or // retrying a claim that timed out. void acquire_lease_at_start(); // requires lease_mutex_ @@ -296,9 +303,15 @@ class CaptureStorageService { // publish. Taken inside cycle_mutex_, never the other way, and only // through a LeaseScope. std::mutex lease_mutex_; - // Lease claims and renewals timed out since the last that succeeded. - // Guarded by lease_mutex_. + // Timeouts that cost the lease since one was last held for 2 x TTL, and + // every one ever counted (which LeaseScope compares, so that a loss is + // counted once). Guarded by lease_mutex_. uint64_t lease_timeouts_ = 0; + uint64_t lease_timeouts_counted_ = 0; + // The lease_id held when publish_lease_state() last looked, and since + // when (track_stable_lease). Guarded by lease_mutex_. + std::string stable_lease_id_; + uint64_t stable_since_ns_ = 0; // When a claim or renewal was first refused by another holder since the // lease was last held; 0 while none has been. Guarded by lease_mutex_. uint64_t held_elsewhere_since_ns_ = 0; diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 95cebf80f..6b3e28a4a 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -1689,6 +1689,72 @@ def test_a_slow_but_healthy_catalog_keeps_its_lease_through_index_passes( assert sorted(captures) == sorted(tensors) +def test_a_catalog_too_slow_to_keep_its_lease_says_so(fake_s3, tmp_path): + """The lease-timeout streak reset on every successful claim, and counted + only claims and renewals that timed out. Against a catalog too slow to + keep a lease -- each claim goes through, then a renewal or a request of + the pass runs out of lease, the writer quarantines, and the next claim + goes through again -- the count went 1, 0, 1, 0 and the knobs were + never named. Every timeout that costs the lease now counts, and the + count clears only once a lease has been held for 2 x TTL. Scaled 1/5: + 0.9 s INSERTs and 0.4 s reads against a 3 s TTL.""" + spool_root = tmp_path / "spool" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + knobs = dict(reconcile_on_start=False, lease_ttl_s=3.0, + publish_timeout_s=1, clickhouse_request_timeout_s=20.0) + warm = _service(_storage_config(fake_s3, catalog.table_prefix, + **knobs), tmp_path / "warm") + warm.start() + warm.stop() + + switch.delay_requests(_slow_catalog(0.9, 0.4)) + service = _service(_storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + **knobs), spool_root) + service.start() + states = [] + stop = threading.Event() + + def _sample(): + while not stop.is_set(): + states.append(service.snapshot()["lease_state"]) + time.sleep(0.1) + + sampler = threading.Thread(target=_sample, daemon=True) + sampler.start() + try: + _stage(spool_root, range(4)) + + def _flush(): + try: + service.flush(40.0) # never drains; stop() ends it + except Exception: # noqa: BLE001 -- "not started" once stopped + pass + + flusher = threading.Thread(target=_flush, daemon=True) + flusher.start() + _wait_for(lambda: service.snapshot()["lease_timeout_error"], + timeout_s=30.0) + snapshot = service.snapshot() + finally: + stop.set() + switch.close() + service.stop() + sampler.join(timeout=5) + + # The claims went through: this is the lease lost after each. + assert "held" in states and "quarantined" in states, states + assert snapshot["lease_timeouts"] >= 3, snapshot + assert snapshot["failed"] is False, snapshot + for knob in ("lease_ttl_s", "clock_skew_s", + "clickhouse_request_timeout_s", "lease_ttl_s / 3"): + assert knob in snapshot["lease_timeout_error"], snapshot + # last_error is whatever failed last -- the knobs when the count + # reached three, the pass the lost lease failed a moment later. + assert "lease" in snapshot["last_error"], snapshot + + def _lease_insert(request: bytes) -> bool: body = request.partition(b"\r\n\r\n")[2] return body.startswith(b"INSERT") and b"_publisher_lease` (term" in body @@ -1762,7 +1828,8 @@ def test_lease_requests_that_keep_timing_out_name_the_knobs_that_bound_them( timed out, quarantined, was refused by its own late row, started over -- and all the snapshot ever said was "curl: Timeout was reached". Once three lease requests in a row time out, the snapshot names the bound - and the knobs that set it, until the lease renews again.""" + and the knobs that set it, until a lease has been held for 2 x TTL + again.""" switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) with _catalog() as (_client, catalog): config = _storage_config( From a427193c6df60f13f7fb02f2c9a7da2269e7cd2f Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 12:18:20 -0400 Subject: [PATCH 12/13] Pin the lease paths the tests left open, and fix two comments Tests: - The in-pass stall test stalled only a catalog INSERT, which quarantines the writer by itself. It now also stalls the replay guard's read, which does not: the lease its deadline passed on is given up at the lease lock's scope, and the test checks it is never reported held over a dead row. - A claim that wrote nothing (every connection refused) goes again a lease tick later, so that flush()'s fast cycles do not hammer a catalog that cannot answer. Nothing pinned it; the new test counts the connections flush() makes while the catalog refuses them (9 in 4 s, 39 with the throttle removed). - Two stall tests checked that the first "quarantined" sample came before 3.0 s, where the quarantine happens at about 2.9 s and samples are 0.1 s apart: a few milliseconds of slack. They now check when the writer actually quarantined, from the snapshot's quarantined_until, which is on time.monotonic()'s clock. Comments: the lease tick is no longer what schedules a renewal -- the lease thread wakes when one falls due, and a stretch under the lease lock renews before its next request -- and renewal_window_ns is the floor the configuration is checked against, not a promise that a renewal starts within half the TTL. --- native/csrc/catalog/lease_coordinator.h | 14 ++- native/csrc/catalog/storage_service.cpp | 14 +-- tests/test_native_capture_storage_live.py | 111 +++++++++++++++++++--- 3 files changed, 117 insertions(+), 22 deletions(-) diff --git a/native/csrc/catalog/lease_coordinator.h b/native/csrc/catalog/lease_coordinator.h index 549c14dec..33b4ede68 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -69,13 +69,19 @@ uint64_t lease_deadline_ns(uint64_t sent_ns, uint64_t lease_ttl_ns, uint64_t clock_skew_ns); // How long a renewal has between when it starts, at the latest, and the -// lease deadline it must finish by. The storage service renews a third of -// the TTL after the claim that stamped the row was sent and looks every -// sixth, so a renewal starts within lease_ttl_ns / 2 of that send: +// lease deadline it must finish by. The storage service's renewal falls due +// a third of the TTL after the claim that stamped the row was sent: its +// lease thread wakes for it, and a stretch holding its lease lock renews +// before the next request it sends. Allowing a sixth of the TTL more for +// whatever holds the lock between requests, a renewal is taken to start +// within lease_ttl_ns / 2 of that send: // // window = lease_ttl_ns / 2 - clock_skew_ns - kLeaseDeadlineMarginNs // -// 0 when the skew leaves no time at all. +// 0 when the skew leaves no time at all. It is the floor the configuration +// is checked against, not a promise: a renewal that starts later still has +// to finish by the deadline, and fails, while the row is live, if it +// cannot. uint64_t renewal_window_ns(uint64_t lease_ttl_ns, uint64_t clock_skew_ns); // The storage service refuses a skew whose renewal window is shorter than diff --git a/native/csrc/catalog/storage_service.cpp b/native/csrc/catalog/storage_service.cpp index b27b23a6b..fd07c42f6 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -59,12 +59,14 @@ bool is_lease_refusal(const CatalogError& exc) { exc.kind() == CatalogError::Kind::kLease; } -// The lease thread's tick, which is also the retry interval for a claim -// another holder refused: a sixth of the TTL, so a renewal due at ttl/3 is -// never more than a tick late. renewal_window_ns (lease_coordinator.h) takes -// the least time a renewal has from this schedule -- it starts within ttl/2 -// of the claim that stamped the row -- so change one and the other must -// follow. +// The lease thread's tick: the longest it sleeps, and the retry interval for +// a claim another holder refused or one that wrote nothing -- a sixth of the +// TTL. A renewal falls due a third of the TTL after the claim that stamped +// the row was sent; the thread wakes for it then, not on the next tick, and +// a stretch holding the lease lock renews before its next request once it +// is due. renewal_window_ns (lease_coordinator.h) allows a tick more than +// that -- a renewal is taken to start within ttl/2 of the send -- so change +// one and the other must follow. uint64_t lease_tick_ns(uint64_t ttl_ns) { return std::max(ttl_ns / 6, 10'000'000ull); } diff --git a/tests/test_native_capture_storage_live.py b/tests/test_native_capture_storage_live.py index 6b3e28a4a..6d4b0ea4b 100644 --- a/tests/test_native_capture_storage_live.py +++ b/tests/test_native_capture_storage_live.py @@ -303,6 +303,8 @@ def __init__(self, host: str, port: int): self._delay_by = None # time.monotonic() of every request stall_requests() held. self.stalled: list[float] = [] + # time.monotonic() of every connection refused while cut. + self.refused: list[float] = [] self._lock = threading.Lock() self._sockets: set[socket.socket] = set() threading.Thread(target=self._accept, daemon=True).start() @@ -327,6 +329,7 @@ def _accept(self): self._sockets.add(client) # held open, never read continue if not self._up: + self.refused.append(time.monotonic()) client.close() continue if (self._late_by > 0 or self._stall_if is not None @@ -1114,6 +1117,14 @@ def _held_but_dead(log): return [sample for sample in log if sample[1] == "held" and not sample[2]] +def _quarantined_at(snapshot, ttl_s: float) -> float: + """When the writer quarantined, on time.monotonic()'s clock: the + quarantine ends one TTL after it began, on the same steady clock. More + precise than the first sample that saw it.""" + assert snapshot["lease_state"] == "quarantined", snapshot + return snapshot["quarantined_until"] - ttl_s + + def _lease_row_left_s(client, prefix) -> float: """Seconds the newest lease row has left on the server's clock; negative once it has expired.""" @@ -1216,9 +1227,13 @@ def test_a_stalled_renewal_gives_up_while_the_lease_row_is_still_live( log = _sample_lease(service, client, catalog.table_prefix, 4.0, origin=stalled_at) assert not _held_but_dead(log), log - quarantined = [t for t, state, _ in log if state == "quarantined"] - assert quarantined and quarantined[0] < 3.0, log snapshot = service.snapshot() + # At the lease deadline, 2.9 s after start()'s claim was sent, + # a moment before stalled_at: before the row can have expired. + # From the quarantine itself, not the first sample to see it, + # which could come a sampling interval later. + quarantined_at = _quarantined_at(snapshot, 3.0) - stalled_at + assert 2.0 < quarantined_at < 2.95, (quarantined_at, log) assert "lease renewal failed" in snapshot["last_error"], snapshot assert "Timeout" in snapshot["last_error"], snapshot assert snapshot["failed"] is False, snapshot @@ -1238,16 +1253,79 @@ def _catalog_insert_but_the_lease(request: bytes) -> bool: return body.startswith(b"INSERT") and b"_publisher_lease` (term" not in body -def test_a_stall_inside_the_index_pass_gives_up_while_the_lease_row_is_live( +def test_a_claim_that_wrote_nothing_goes_again_a_tick_later( fake_s3, tmp_path): + """A claim that failed before its INSERT went out -- here every + connection is refused -- wrote nothing, so it does not quarantine the + writer; and so that flush()'s fast cycles do not hammer a catalog that + cannot answer, the next claim waits a lease tick (a sixth of the TTL), + not a cycle.""" + spool_root = tmp_path / "spool" + switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) + with _catalog() as (_client, catalog): + ttl = 6.0 # a 1 s tick + config = _storage_config( + fake_s3, catalog.table_prefix, clickhouse_port=switch.port, + reconcile_on_start=False, lease_ttl_s=ttl, publish_timeout_s=1) + service = _service(config, spool_root) + service.start() + try: + _stage(spool_root, range(2)) + switch.cut() + # The renewal fails and quarantines; once that ends, every claim + # fails to connect, and writes nothing. + _wait_for(lambda: service.snapshot()["lease_state"] + == "quarantined", timeout_s=ttl) + _wait_for(lambda: service.snapshot()["lease_state"] + == "reacquiring", timeout_s=ttl + 2) + + def _flush(): + try: + service.flush(4.0) + except Exception: # noqa: BLE001 -- only the traffic counts + pass + + flusher = threading.Thread(target=_flush, daemon=True) + watched_from = time.monotonic() + flusher.start() + flusher.join(timeout=10) + watched = time.monotonic() - watched_from + refused = [t for t in switch.refused if t >= watched_from] + snapshot = service.snapshot() + finally: + switch.close() + service.stop() + + # Not quarantined by claims that wrote nothing. + assert snapshot["lease_state"] == "reacquiring", snapshot + # One claim a tick, of up to three connection attempts each (the + # client retries a refused connection): about 12 in 4 s, where + # flush()'s cycles, 50 ms apart, would make several times that. + assert len(refused) <= 3 * (watched / 1.0 + 2), (len(refused), watched) + + +def _replay_guard_read(request: bytes) -> bool: + body = request.partition(b"\r\n\r\n")[2] + return (body.startswith(b"SELECT store_id, toString(pack_id) FROM") + and b"_pack_inventory" in body) + + +@pytest.mark.parametrize("stalled", [_catalog_insert_but_the_lease, + _replay_guard_read], + ids=["insert", "read"]) +def test_a_stall_inside_the_index_pass_gives_up_while_the_lease_row_is_live( + fake_s3, tmp_path, stalled): """The index pass holds the lease lock across its catalog requests -- the version claim, the descriptor INSERTs, the publish and its read-backs -- and those were bounded only by the client's request timeout. One that stalled kept the lease thread from renewing: the row expired while the snapshot still said "held", until the 20 s request timeout. The lease deadline now bounds every request sent under the lease, not only the - lease's own, so the stalled INSERT fails, and the lease quarantines, - while the row is still live.""" + lease's own, so the stalled request fails, and the lease quarantines, + while the row is still live. A stalled INSERT has an unknown outcome and + quarantines the writer itself; a stalled read (the replay guard) does + not, and it is the lease lock's scope that abandons the lease its + deadline passed on, rather than go on calling it held.""" spool_root = tmp_path / "spool" switch = _Switch(CLICKHOUSE_HOST, CLICKHOUSE_HTTP_PORT) with _catalog() as (client, catalog): @@ -1258,17 +1336,26 @@ def test_a_stall_inside_the_index_pass_gives_up_while_the_lease_row_is_live( service = _service(config, spool_root) service.start() try: - # Every catalog INSERT but the lease's own stalls, so the lease - # thread alone could keep the row alive -- if it got the lock. - switch.stall_requests(_catalog_insert_but_the_lease) + # Every such request stalls, while the lease's own go through, + # so the lease thread alone could keep the row alive -- if it + # got the lock. + switch.stall_requests(stalled) tensors = _stage(spool_root, range(2)) _wait_for(lambda: switch.stalled, timeout_s=10.0) - log = _sample_lease(service, client, catalog.table_prefix, 8.0, + log = _sample_lease(service, client, catalog.table_prefix, 2.5, origin=switch.stalled[0]) + _wait_for(lambda: service.snapshot()["lease_state"] + == "quarantined", timeout_s=2.0) + snapshot = service.snapshot() + log += _sample_lease(service, client, catalog.table_prefix, 3.0, + origin=switch.stalled[0]) assert not _held_but_dead(log), log - quarantined = [t for t, state, _ in log if state == "quarantined"] - assert quarantined and quarantined[0] < 3.0, log - assert service.snapshot()["failed"] is False + # By the lease deadline, at most 2.9 s after the stalled + # request went out (the lease renews before each request that + # finds it due). + quarantined_at = _quarantined_at(snapshot, 3.0) - switch.stalled[0] + assert quarantined_at < 2.95, (quarantined_at, log) + assert snapshot["failed"] is False switch.restore() service.flush(30.0) From fe5f06399831b4743332dad4c481945642a677ec Mon Sep 17 00:00:00 2001 From: Alan Liu Date: Mon, 28 Sep 2026 13:00:06 -0400 Subject: [PATCH 13/13] Say which stalled holder still keeps the lease past its row #154's note on sweep_spool_on_start said a stalled holder keeps the lease locally and starts new batches until a renewal or publish is refused. On this branch a holder whose catalog requests stall has them cut off at the lease deadline, which falls before its row lapses, and a cycle's lease check abandons a lease past that deadline (LeaseScope), so it starts no batch after it. Only a holder whose whole process stalls keeps the lease locally past its row: until it resumes and checks again, or, after a system suspend (the steady clock the deadline runs on does not count one), until a renewal or publish is refused. --- native/csrc/catalog/storage_service.h | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/native/csrc/catalog/storage_service.h b/native/csrc/catalog/storage_service.h index a088ff0cc..74d697ee3 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -135,11 +135,16 @@ struct StorageServiceConfig { // UploadPending does not stop when the lease is lost: a holder that is // quarantined, or refused a renewal or publish, while a batch is in // flight finishes that batch (which can outlast the TTL), and only its - // later cycles upload nothing while it holds no lease. A stalled one - // still holds the lease locally and starts new batches until a renewal - // or publish is refused. Two on different (database, table_prefix) pairs - // each hold a lease and upload freely. The spool itself is not locked; - // one process per spool is the caller's job. + // later cycles upload nothing while it holds no lease. One whose catalog + // requests stall gives the lease up at its deadline, before its row + // lapses: requests made under the lease are cut off there, and a cycle's + // check abandons a lease past it (LeaseScope), so no batch starts after + // that. Only a holder whose whole process stalls keeps the lease locally + // past its row: until it resumes and next checks, or -- after a system + // suspend, which the steady clock the deadline runs on does not count -- + // until a renewal or publish is refused. Two on different (database, + // table_prefix) pairs each hold a lease and upload freely. The spool + // itself is not locked; one process per spool is the caller's job. bool sweep_spool_on_start = true; bool reconcile_on_start = true; };