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..425117aec 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,18 @@ 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(); +} + +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 438c88dff..787c86d87 100644 --- a/native/csrc/catalog/catalog_writer.h +++ b/native/csrc/catalog/catalog_writer.h @@ -89,6 +89,28 @@ class CatalogWriter { PublisherLease renew_lease(); void release_lease(); const PublisherLease* held_lease() const { return leases_->lease(); } + // 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(); + // 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/clickhouse_client.cpp b/native/csrc/catalog/clickhouse_client.cpp index 230233455..473c9e5ad 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 @@ -121,6 +134,19 @@ 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; +// 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) { + 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 +245,63 @@ 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, + 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; +} + +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 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) { + 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\""); @@ -399,21 +482,46 @@ 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(); + // 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); // 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 @@ -431,7 +539,8 @@ std::vector ClickHouseClient::execute( } } - const auto perform = [&]() { + 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"); @@ -470,10 +579,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 +588,69 @@ 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 timed_out(error, 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(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); } + 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). + std::string error = std::string("curl: ") + + curl_easy_strerror(attempt.code); + if (!attempt.detail.empty()) error += ": " + attempt.detail; + error += bounded_by(); + if (number > 1) { + error += " (attempt " + std::to_string(number) + ")"; + } + throw timed_out(error, sent); + } std::string error; bool retry = false; if (attempt.code != CURLE_OK) { @@ -503,6 +667,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 timed_out(error, sent); + } retry = read && attempt.status >= 500 && attempt.status < 600 && (code < 0 || transient_clickhouse_error(code)); } @@ -510,13 +684,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..8b449dfd7 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,83 @@ 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, 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 + // 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. +// +// 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. + 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, + std::function before_request = {}); + ~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); + // 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(); + + // 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_; }; // clickhouse-driver's client-side `%(name)s` substitution: one @@ -95,6 +171,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 @@ -114,6 +197,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). @@ -129,13 +216,22 @@ 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 // 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. 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 // than as a 200 whose truncated body would parse as rows. A URL setting: @@ -143,10 +239,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/conformance_catalog.cpp b/native/csrc/catalog/conformance_catalog.cpp index d82ee5a5a..842e88f35 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) + @@ -1086,13 +1106,21 @@ 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); 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/indexer.cpp b/native/csrc/catalog/indexer.cpp index 9281ea00c..25793b897 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,14 @@ uint64_t NativeIndexer::allocate_version() { } IndexResultData NativeIndexer::index(const std::vector& refs) { - IndexResultData result; + IndexPlan planned = plan(refs); + read(&planned); + return commit(&planned); +} + +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 +206,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 +217,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 +255,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 +263,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,6 +287,35 @@ 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()) { uint64_t version = allocate_version(); uint64_t descriptor_inserts = 0; const auto write_batches = [&](uint64_t at_version) { @@ -343,7 +393,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..d6e7050fa 100644 --- a/native/csrc/catalog/indexer.h +++ b/native/csrc/catalog/indexer.h @@ -53,13 +53,41 @@ 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(); diff --git a/native/csrc/catalog/lease_coordinator.cpp b/native/csrc/catalog/lease_coordinator.cpp index b54f49f56..e7045a4be 100644 --- a/native/csrc/catalog/lease_coordinator.cpp +++ b/native/csrc/catalog/lease_coordinator.cpp @@ -9,8 +9,47 @@ 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, 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) { + ms = std::max(ms, 1); + 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; +} + } // 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(); @@ -32,14 +71,75 @@ 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) 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( + 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 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 + // 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. The storage service + // therefore does not count a refusal by its own claim rows towards its + // 2 x TTL latch (refused_by_own_claims()). + 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, attempt_ms), + 1)); + } + (*settings)["max_execution_time"] = seconds_setting(attempt_ms); + (*settings)["lock_acquire_timeout"] = seconds_setting(attempt_ms); + (*settings)["timeout_overflow_mode"] = "throw"; } PublisherLease LeaseCoordinator::acquire(const std::string& holder) { @@ -70,13 +170,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(); } @@ -102,20 +202,53 @@ 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; - insert(term, lease_id, holder); + // 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(); + 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); + } 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}) { @@ -132,7 +265,9 @@ 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, + deadline_ns}; return *lease_; } lease_.reset(); @@ -143,12 +278,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"); @@ -160,6 +295,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; } @@ -185,12 +321,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"; } @@ -214,8 +350,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) " @@ -224,7 +359,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, @@ -234,6 +369,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 2c4df49c0..33b4ede68 100644 --- a/native/csrc/catalog/lease_coordinator.h +++ b/native/csrc/catalog/lease_coordinator.h @@ -15,16 +15,83 @@ #define DMI_CATALOG_LEASE_COORDINATOR_H #include +#include #include #include #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). 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 +// 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 +// 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'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. 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 +// 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,6 +108,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, + // and the lease deadline that follows from it (lease_deadline_ns). + uint64_t sent_ns = 0; + uint64_t deadline_ns = 0; }; struct LeaseHead { @@ -51,6 +122,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 { @@ -89,6 +161,19 @@ 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_; } + // 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(); @@ -115,12 +200,30 @@ 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; + // 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_; + 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_; + // 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/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.cpp b/native/csrc/catalog/storage_service.cpp index cc1254c96..fd07c42f6 100644 --- a/native/csrc/catalog/storage_service.cpp +++ b/native/csrc/catalog/storage_service.cpp @@ -59,15 +59,70 @@ 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. +// 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); } +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] { 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 (...) { + } + } + + LeaseScope(const LeaseScope&) = delete; + LeaseScope& operator=(const LeaseScope&) = delete; + + private: + 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) : config_(std::move(config)), s3_(config_.s3), @@ -83,6 +138,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,10 +182,53 @@ 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 } + // 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 @@ -120,11 +239,6 @@ void CaptureStorageService::start() { std::vector recovered; std::string error; if (spool_.Recover(&recovered, &error) != dmi_store::SpoolStatus::kOk) { - try { - std::lock_guard lease(lease_mutex_); - if (writer_.held_lease() != nullptr) writer_.release_lease(); - } catch (...) { - } throw std::runtime_error("storage service: spool recovery failed: " + error); } @@ -132,44 +246,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 { - std::lock_guard lease(lease_mutex_); - 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; - } - { - std::lock_guard lease(lease_mutex_); - publish_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() { @@ -179,7 +278,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; @@ -188,7 +289,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; @@ -204,6 +305,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( @@ -280,7 +390,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 @@ -351,10 +461,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(); } @@ -434,11 +548,21 @@ void CaptureStorageService::index_bounded(std::vector refs, work.pop_back(); IndexResultData result; try { - 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 + // 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_.commit(&plan); } catch (const CatalogError& exc) { if (exc.kind() == CatalogError::Kind::kBatchTooLarge && batch.size() > 1) { const size_t middle = batch.size() / 2; @@ -534,7 +658,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); } @@ -595,25 +719,41 @@ 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 stop_requested_; }); - if (stop_requested_) return; + wake_.wait_for(lock, std::chrono::nanoseconds(wait_ns), + [this] { return lease_stop_requested_; }); + if (lease_stop_requested_) return; } { std::lock_guard lock(state_mutex_); if (failure_) return; } - std::lock_guard lease(lease_mutex_); + 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 @@ -626,51 +766,134 @@ 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(); } } 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 -- 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; - 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; } +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&) { + 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; + writer_.abandon_lease(); + 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()) 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_) + + " 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) + + " 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: " + + latest; + record_error(message); + } + std::lock_guard lock(state_mutex_); + state_.lease_timeouts = lease_timeouts_; + state_.lease_timeout_error = message.substr(0, 1024); +} + +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; + 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 // 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); - last_renew_ns_ = steady_ns(); return; } catch (const CatalogError& exc) { if (!is_lease_refusal(exc) || config_.start_lease_wait_ns == 0) throw; @@ -685,6 +908,47 @@ 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, 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); + // 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 " + "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)); + } } } } @@ -718,13 +982,20 @@ 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; } - last_renew_ns_ = steady_ns(); held_elsewhere_since_ns_ = 0; next_claim_ns_ = 0; { @@ -743,8 +1014,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. @@ -759,6 +1047,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 3c798e04a..74d697ee3 100644 --- a/native/csrc/catalog/storage_service.h +++ b/native/csrc/catalog/storage_service.h @@ -38,6 +38,24 @@ // (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 +// reconcile sends under the lease lock -- has to be answered by the lease +// 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 +// 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 #include @@ -98,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 @@ -115,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; }; @@ -151,6 +176,15 @@ 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 + // 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; }; @@ -162,9 +196,14 @@ 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 -- 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 + // later, and reconciles then. void start(); // Run cycles until one finds the spool empty with every uploaded pack @@ -191,7 +230,28 @@ 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. + // 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 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(); + // 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. @@ -200,13 +260,30 @@ 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. + // 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, 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); + // 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_ // Whether the writer holds a lease, taking a fresh one when it has none // 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_. @@ -226,10 +303,20 @@ 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. + // 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_; - uint64_t last_renew_ns_ = 0; // 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; @@ -237,6 +324,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_; @@ -245,11 +335,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/src/dmi/storage/native_capture.py b/src/dmi/storage/native_capture.py index aed635898..ebd9f76c4 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,11 @@ 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; 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 683d27150..6d4b0ea4b 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 @@ -275,8 +276,14 @@ 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).""" + """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, 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) @@ -284,10 +291,33 @@ 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 + # (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] = [] + # 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() + @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: @@ -299,8 +329,15 @@ 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 + 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 try: upstream = socket.create_connection(self._target) except OSError: @@ -326,6 +363,100 @@ def _pump(source, sink): except OSError: pass + def _look_then_route(self, client): + """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, and each request by + what delay_requests() says; 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]) + 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) + 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.""" + 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 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: @@ -346,6 +477,10 @@ 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 + self._delay_by = None def close(self): self.cut() @@ -622,7 +757,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() @@ -953,6 +1088,919 @@ 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 _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]] + + +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.""" + 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 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 + 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 + + # 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_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 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): + 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 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, 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 + # 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) + 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 _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 + + +@pytest.mark.parametrize("schema", ["installed", "fresh"]) +def test_start_survives_a_first_lease_read_slower_than_its_bound( + 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. 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) + 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( + 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 (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() + + +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 + + +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 _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 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 + + +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 + 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 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( + 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, 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, + 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 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 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. + 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] @@ -1046,6 +2094,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_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..92370b364 --- /dev/null +++ b/tests/test_native_lease_request_bound.py @@ -0,0 +1,677 @@ +"""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 socket +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 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 + # (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 + # When each statement arrived, by prefix of its body. + self.arrivals: list[tuple[float, str]] = [] + 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)) + fake.arrivals.append((time.monotonic(), 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) + 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]) + 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 + 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: + 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. 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 + 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 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. + 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 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 + + +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 + + +@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 + + +@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 + 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 + + +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() + + +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 -------------------------------------- + + +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 "