From 129d043b223e2f471bdfdef23f17f79e55a9ed37 Mon Sep 17 00:00:00 2001 From: "liquan.eth" Date: Fri, 21 Aug 2026 19:55:43 +0800 Subject: [PATCH 1/4] feat(debug-trace-server): inbound admission control and response-size caps MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Nothing bounded what clients could ask of this process. Every existing concurrency cap is outbound — the witness, data and R2 semaphores limit what we ask of others, and they are unbounded waits, so overflow could only ever surface as a timeout. EVM tracing runs inline on the runtime's worker threads, so enough concurrent requests starve chain sync, the accept loop and the metrics exporter along with each other. Requests beyond the configured budget are now refused immediately with -32013 "Request queue is full", matching mega-reth's ConcurrencyLimiter byte for byte so existing client backoff applies unchanged. The gate is split in two, and the split is load-bearing rather than stylistic. AdmissionLayer sits inside ConcurrentBatchLayer — which decomposes batches into per-entry calls rather than delegating to an inner batch, so an inner layer sees single calls and every batch entry — and only ever runs a non-blocking CAS against max_concurrent + max_queue. The execution permit is taken in the handler, after the response cache misses. CancelGuard arms on a request's first poll and the handlers record their arrival synchronously in that same poll, so a middleware gate that parked before the handler would record a cancellation with no matching arrival for every client that hung up while queued: negative, permanent drift in the accounting identity, worst under exactly the overload the gate exists for. A layer that only CAS-es keeps arm and arrival in one poll, and the permit wait then sits after the arrival is already booked. The placement pays three more ways: a cache hit never takes a permit, the typed RequestShape is already in hand so the heavy-tracer sub-cap costs no second parse of attacker-controlled JSON, and what the permits count is blocks actually being fetched and replayed. Each handler mints its deadline once and passes it to both the permit wait and the fetch, so the queue is carved out of --block-fetch-timeout rather than added on top of it. The reserve held back for the witness stage falls back to half the budget when --witness-timeout does not fit inside --block-fetch-timeout, a legal pair that would otherwise leave a zero-length wait and silently reduce --admission-max-queue to a no-op. Two bugs in the reference implementation are deliberately not carried over: its wait future is created after the capacity check, so a permit freed in that window is never observed, and raising a limit never wakes parked waiters. Both are avoided by using a resizable FIFO Semaphore — grow with add_permits, shrink with forget_permits plus a debt counter settled on release — and both directions are regression-tested. Occupancy is counted rather than derived from available permits: once a shrink leaves debt behind, that difference reports the new limit, so the admin RPC would have answered a retune by claiming it had already taken effect while every old holder was still resident. Every struct-logger request is heavy, including the bare default one. It emits a record per executed opcode, and the only thing separating it from its already- heavy flagged sibling is a flag that changes the size of that output rather than its kind — so an opts-less debug_trace* call is limited by --admission-heavy-max-concurrent. --max-response-size is checked at this server's own serialization point, so an over-limit body is dropped before it can be copied again into the JSON-RPC envelope; --max-batch-response-size separately caps the assembled batch, because a batch retains every completed entry's body until it finishes and that accumulation, not any single response, is what has previously exhausted this process. Startup logs both the heavy and the overall concurrency-times-size products; neither bounds a tracer's intermediate allocations, and the doc says so. --admin-addr starts a second listener, loopback enforced, on its own thread and runtime — inline tracing on the main runtime would otherwise starve it exactly when it is needed — serving admin_getConcurrencyLimit / admin_setConcurrencyLimit so the limits can be retuned without a restart. It carries no RPC middleware, so a saturated public port cannot shed the call that relieves it. A shed records the balanced pair shape="shed" / reason="overloaded" from inside the request future, where the ERROR_SELF_REPORTED task-local suppresses settle_response's unattributed drift arm; settle_response itself is unchanged. Verified on a live server: 30 concurrent requests against a 16-capacity gate shed exactly 14, the balanced pair matched exactly, the per-method identity summed, and the drift alarm stayed at zero; shrinking maxConcurrent 4->1 with four permits held reported 4 executing and agreed with the Prometheus gauge. The layer-order pin, the task-local claim, and the occupancy fix were each mutation-tested. Co-Authored-By: Claude Opus 5 (1M context) --- AGENTS.md | 17 +- README.md | 49 ++ bin/debug-trace-server/Cargo.toml | 2 +- bin/debug-trace-server/src/admin.rs | 343 +++++++++ bin/debug-trace-server/src/admission.rs | 768 +++++++++++++++++++ bin/debug-trace-server/src/data_provider.rs | 115 ++- bin/debug-trace-server/src/main.rs | 433 ++++++++++- bin/debug-trace-server/src/metrics.rs | 181 ++++- bin/debug-trace-server/src/response_cache.rs | 28 + bin/debug-trace-server/src/rpc_middleware.rs | 278 ++++++- bin/debug-trace-server/src/rpc_service.rs | 386 +++++++++- 11 files changed, 2491 insertions(+), 109 deletions(-) create mode 100644 bin/debug-trace-server/src/admin.rs create mode 100644 bin/debug-trace-server/src/admission.rs diff --git a/AGENTS.md b/AGENTS.md index b1e0d63e..0af66393 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -109,7 +109,20 @@ Two operating modes: The server includes an HTTP response cache (`quick_cache`) for pre-serialized JSON and a `DataProvider` with single-flight request coalescing. Responses are serialized exactly once, straight from the trace output into raw JSON bytes (`RawJson`) spliced verbatim into the reply; the cache shares those bytes by `Arc`, so a hit never re-parses or re-serializes the JSON tree. Inbound JSON-RPC batch entries execute concurrently as independent runtime tasks through the regular per-request pipeline (synchronous trace CPU parallelizes too; spawned-entry CPU folds back into `x-execution-time-ns`/the CPU metric via a response extension) (`rpc_middleware.rs`, bounded by `--batch-item-concurrency`, default 16; 1 restores jsonrpsee's sequential behavior; batch shape observable via `debug_trace_batch_size`), so a batch answers near its slowest entry instead of the sum of its entries. +Inbound admission control (`admission.rs`) bounds what clients may ask of the process — every other concurrency cap here is outbound, and unbounded inline EVM tracing otherwise starves chain sync, the accept loop and the metrics exporter along with the requests — shedding with `-32013 "Request queue is full"`, mega-reth's `ConcurrencyLimiter` contract byte for byte so existing client backoff applies unchanged. +It is deliberately split in two: `AdmissionLayer` (installed *inside* `ConcurrentBatchLayer`, so it sees single calls and every batch entry, since that layer decomposes batches into per-entry `call`s rather than delegating to an inner `batch`) only ever runs a non-blocking CAS against `--admission-max-concurrent` + `--admission-max-queue`, while the execution permit is taken in the handler *after* `check_cache` misses. +That placement is load-bearing, not stylistic: `CancelGuard` arms on a request's first poll and the handler records its arrival synchronously in that same poll, so a middleware gate that parked before the handler would record a cancellation with no matching arrival for every client that hung up while queued — negative, permanent identity drift, worst under exactly the overload the gate exists for; a layer that only CAS-es preserves the invariant by construction, and the permit wait then sits after the arrival is already booked. +It also means a response-cache hit never takes a permit, the typed `RequestShape` is already in hand so the heavy-tracer sub-cap (`--admission-heavy-max-concurrent`, covering `prestateTracer`/JS/`muxTracer` and *every* struct-logger request including the bare default — the flags separating the two struct-logger shapes change output size, not kind — taken *before* the ordinary permit, so heavy requests never occupy execution permits while waiting for each other) costs no second parse of attacker-controlled JSON, and what the permits count is blocks actually being fetched and replayed. +The permit wait is clamped to `deadline - witness_timeout` (`DataProvider::permit_cutoff`), so a request that queued away the budget its witness fetch still needs is refused now rather than started and timed out later — the difference between "may reject" and "times out"; the reserve falls back to half the budget when `--witness-timeout` does not fit inside `--block-fetch-timeout` (a legal pair, since the witness sub-deadline is a `min` against the outer one), because reserving all of it would leave a zero-length wait and silently reduce `--admission-max-queue` to a no-op. +Every handler mints its deadline once and passes it to both the permit wait and the fetch (`get_block_data_by_hash`/`get_block_data_for_tx` take it as a parameter for exactly this reason), so the queue is carved out of `--block-fetch-timeout` rather than added on top of it. +`debug_getCacheStatus` and its `timed_` alias are the sole exemption (matched on the `timed_`-stripped name, since the gateway adds that prefix by default and a bare-name comparison would never match production traffic); `assert_admission_covers_module` fails startup if a newly registered method escapes `metrics::GATED_METHODS`. +The limiter uses a resizable FIFO `Semaphore` (shrink via `forget_permits` plus a debt counter settled on release) rather than the reference implementation's counter+`Notify`, which has a lost wakeup (its `Notified` is created *after* the capacity check) and never wakes parked waiters on a raise — both regression-tested here. +Occupancy is counted, never derived as `limit - available_permits`: once a shrink leaves debt behind that difference reports the *new* limit, so the admin RPC would answer a retune by claiming it had already taken effect while every old holder was still resident (`occupancy_stays_truthful_while_a_shrink_is_outstanding`). +`--max-response-size` is checked at this server's own serialization point (`RawJson::try_new` in `serialize_reply`/`compute_block_trace`, counted on `debug_trace_response_oversized_total`, classified `TraceError::Request` so an oversized ask never evicts a good block), and `--max-batch-response-size` separately caps the assembled batch — different bounds, because a batch retains every completed entry's body until it finishes, and that accumulation rather than any single response is what has previously exhausted the process; both `heavy_max_concurrent x max_response_size` and `max_concurrent x max_response_size` are logged at startup, and neither bounds a tracer's intermediate allocations — a per-transaction-count gate would, and is not implemented. +`--admin-addr` (loopback enforced at startup, off unless set) serves `admin_getConcurrencyLimit`/`admin_setConcurrencyLimit` on a second listener with no RPC middleware — so a saturated public port cannot shed the call that relieves it — running on its own thread and runtime, since inline EVM tracing on the main runtime would otherwise starve it exactly when it is needed; `maxConcurrent = 0` is refused as unrecoverable. Every inbound request is accounted for exactly once, so "did any client see a timeout?" is a metric lookup rather than an inference: arrivals are counted by `debug_trace_request_shape_total` before the first await, and each request then lands in exactly one of `debug_trace_rpc_requests_total` (served), `debug_trace_rpc_errors_total{reason}` (failed), or `debug_trace_requests_cancelled_total` (client hung up — recorded from the drop of the request future in `rpc_middleware.rs`, the only layer that observes single calls and batch entries alike), so `shape = requests + errors + cancelled` holds per method. +A shed adds the balanced pair `shape="shed"` / `reason="overloaded"`, recorded by the admission layer from *inside* the returned future — `record_rpc_error` sets the `ERROR_SELF_REPORTED` task-local that tells `settle_response` this non-framework `-32013` is already accounted for, which is what keeps `settle_response` unchanged; recorded from the layer's synchronous prefix instead, every shed would double-count its error and false-fire the `unattributed` drift alarm (`admission_shed_keeps_the_identity_closed` pins both). +A permit refused after the handler already recorded its arrival contributes the outcome side alone. Requests the framework answers before any handler runs (unknown method, malformed top-level params, unparsable batch entries — recognized by their framework error codes) are folded in by the same middleware as the balanced pair `shape="rejected"` / `reason="rejected"`, an unrecorded error with a non-framework code lands error-side only on `reason="unattributed"` (a handler ran and recorded its arrival but bypassed the error funnel — a code-drift alarm that must stay at zero), and the opts-less `trace_*` methods record their `default` arrival at handler entry; the only deliberate approximation is a batch the server itself aborts over the response-size cap (its killed entries record no outcome rather than masquerade as client hangups) and batch entries that never started when the connection died (on neither side, so `cancelled` undercounts torn-down oversized batches). The identity is pinned end-to-end by `accounting_identity_holds_end_to_end` in `rpc_middleware.rs`, which drives every terminal path through a real server under a draining local metrics recorder. The `reason` label splits outcomes that share a JSON-RPC code — `deadline_witness` / `deadline_block` / `not_found` / `invalid_params` / `trace_failed` / `internal` — because a blown witness deadline and an unknown transaction both leave as `-32001` and only the first is an incident; the whole `(method, reason)` grid is pre-registered so an alert on `deadline_witness` reads zero instead of missing from boot. @@ -163,13 +176,15 @@ The background chain-sync prefetch routes by freshness against the last observed | `bin/debug-trace-server/src/rpc_middleware.rs` | Concurrent execution of inbound JSON-RPC batch entries | | `bin/debug-trace-server/src/data_provider.rs` | Block data fetching with single-flight coalescing | | `bin/debug-trace-server/src/block_data_cache.rs` | Bounded in-memory `BlockData` cache keyed by block hash | +| `bin/debug-trace-server/src/admission.rs` | Inbound admission gate: resizable FIFO limiter, guards, `RpcServiceT` layer | +| `bin/debug-trace-server/src/admin.rs` | Loopback-only `admin_*` listener for retuning the gate at runtime | | `bin/debug-trace-server/src/r2_witness.rs` | Direct-from-R2 witness source (light decode, deadline-aware) | | `bin/debug-trace-server/src/server_db.rs` | Defines + implements the bin-local `BlockStore` trait (backed by `stateless-db`) | ## Test Organization Unit tests are embedded in source files alongside the code they test. -Integration tests live in `bin/debug-trace-server/tests/` (6 modules: cache_metrics, block_tag, consistency, performance, timing_header, prune) and in `bin/stateless-validator/tests/integration.rs` (CLI parsing, mock-RPC pipeline, mainnet single-block validation). +Integration tests live in `bin/debug-trace-server/tests/` (6 modules: cache_metrics, block_tag, compression, consistency, performance, timing_header) and in `bin/stateless-validator/tests/integration.rs` (CLI parsing, mock-RPC pipeline, mainnet single-block validation). Test data (block JSON files, contract bytecode, witness data) is stored in `test_data/`. ## Version Control diff --git a/README.md b/README.md index 095d62e8..7cb0bf5c 100644 --- a/README.md +++ b/README.md @@ -116,6 +116,45 @@ Each entry still goes through the regular per-request pipeline — response cach `--batch-item-concurrency` (default 16) bounds how many entries of one batch run at once, so a single huge batch cannot monopolize downstream resources against concurrently served requests; set it to 1 to restore sequential execution. The `debug_trace_batch_size` histogram records entries per inbound batch, and CPU burned inside spawned entries is folded back into `x-execution-time-ns` and the request CPU metric, so batch requests do not under-report their cost. +**Admission control:** +Every request is checked against a process-wide capacity budget before any work happens, so an offered load beyond what this server can serve is refused immediately instead of degrading everything already in flight. +Without it the only backpressure is that all runtime workers are busy tracing, which starves chain sync, the accept loop and the metrics exporter along with the requests themselves; the outbound witness/data/R2 caps bound what we ask of others, never what clients ask of us. +Refused requests are answered `-32013 "Request queue is full"`, matching mega-reth's `ConcurrencyLimiter` byte for byte so a client or gateway that already backs off for the node backs off for this server too. +The gate has two stages. +Arrival is a non-blocking check against `--admission-max-concurrent` + `--admission-max-queue`: past that total, the request is shed on the spot. +An admitted request then waits for one of `--admission-max-concurrent` execution permits, taken only once the response cache has missed — a cache hit costs microseconds and is never queued behind a cold trace — and given up if the wait would leave too little of the request's budget for the witness fetch, which is what turns a full queue into a prompt rejection rather than a deadline error. +The wait is carved *out of* the request's `--block-fetch-timeout` budget rather than added on top of it, so total client latency stays bounded by that flag however long the queue was; the derived maximum wait (`--block-fetch-timeout` less the witness reserve) is logged at startup as `max_permit_wait_ms`. +Entries of a JSON-RPC batch admit individually, so one large batch is metered like the equivalent single calls rather than passing as one unit. +`debug_getCacheStatus` (and its `timed_` alias) is the sole exemption: it does no I/O, and shedding the one endpoint that reports what the server is doing, precisely while it is shedding, would be self-defeating. +Sizing is not a core count — roughly 2% of a trace request is CPU, the rest is waiting on the upstream node and R2 — so derive `--admission-max-concurrent` from measured service time (`throughput x mean_handler_seconds`), and read `--admission-max-queue` as latency: queue depth over service rate is how long a request waits, so at 1000 blocks/s a 1000-deep queue is one second. +The defaults sit above the highest occupancy this server has been measured serving cleanly, so they bound a previously unbounded process without throttling a known-good workload; tighten them once `debug_trace_admission_in_flight` and `debug_trace_admission_permit_wait_seconds` show what production actually does. +Memory-hungry tracers additionally pass `--admission-heavy-max-concurrent`, a much smaller budget: one such response has been measured near a gigabyte. +That set is `prestateTracer`, JS tracers, `muxTracer`, and **every struct-logger request** — both the bare default (a `debug_trace*` call with no `tracer`) and one with non-default flags, since the flags change the size of that output rather than its kind, and a struct logger emits a record per executed opcode. +Note the consequence: an opts-less `debug_traceBlockByNumber` is a heavy request, so a client that sends no tracer is limited to `--admission-heavy-max-concurrent` at a time; raise that flag if such traffic is a normal part of your workload. +Startup logs both `heavy_max_concurrent x max_response_size` and `max_concurrent x max_response_size` — the first bounds the shapes that can actually reach the response cap, the second is the theoretical ceiling if every admitted request returned a maximal body — so they can be checked against the host's memory limit. +Neither covers a tracer's *intermediate* allocations, which nothing here bounds; a per-transaction-count gate would be needed for that and is not implemented. +Watch `debug_trace_rpc_errors_total{reason="overloaded"}` for shedding, `debug_trace_admission_in_flight` / `debug_trace_admission_executing` for occupancy (queue depth is their difference), and the `debug_trace_admission_max_*` gauges for what is actually in effect, since the limits are changeable at runtime. +Disable the whole mechanism with `--admission-disabled`. + +**Response size limits:** +`--max-response-size` (default 256MB) caps one serialized reply and `--max-batch-response-size` (default 1GB) caps a whole assembled batch response; both bodies are discarded rather than returned, and an over-limit single response is counted on `debug_trace_response_oversized_total{method}`. +They bound different things: a batch retains every completed entry's body until the batch finishes, so its memory is the sum of its entries rather than the largest of them, and left unbounded that accumulation — not any single response — is what has previously exhausted this process. +The single-response check runs where this server serializes the reply, so an over-limit body is dropped before it can be copied again into the JSON-RPC envelope; the framework's own cap is the backstop. + +**Runtime retuning:** +`--admin-addr` (e.g. `127.0.0.1:8546`, off unless set) starts a second RPC listener serving `admin_getConcurrencyLimit` and `admin_setConcurrencyLimit`, which change the admission limits without a restart: + +```bash +curl -s http://127.0.0.1:8546 -H 'content-type: application/json' \ + -d '{"jsonrpc":"2.0","id":1,"method":"admin_setConcurrencyLimit","params":[256,4096,4]}' +``` + +Parameters are `[maxConcurrent, maxQueueSize, heavyMaxConcurrent]`, each optional — omitted fields are left alone — and the call returns the resulting limits plus current occupancy. +Lowering a limit below current occupancy aborts nothing; it stops admitting until the excess drains. +Zero execution permits is refused, since it would park every subsequent request with nothing left running to release one. +The listener carries no admission or accounting middleware, so a saturated public port can never shed the call that relieves it, and it runs on its own thread and runtime, so inline EVM tracing on the main runtime cannot starve it — the moment it is needed most. +It has no authentication and its setters can throttle request serving, so a non-loopback bind is refused at startup; reach it through a port-forward or a sidecar. + **Response compression:** Responses negotiate gzip/zstd per request via the client's `Accept-Encoding` header; clients that do not send it keep receiving identity bodies, so nothing changes for consumers that have not opted in. Bodies under 4 KiB are always served identity: compressing them would cost a per-response encoder allocation and downgrade `Content-Length` to chunked framing for a few dozen saved bytes. @@ -172,6 +211,16 @@ Any single witness-chain RPC attempt under a deadline is additionally capped at The round's last hop, and every hop of a single-provider chain, takes the remainder whole under the ceiling instead, so a stalled endpoint (or a saturated concurrency permit — waits are deadline-bounded too) can never consume the stage while a rotation is still worth reserving for, and a slow-but-honest transfer is never structurally condemned; the witness decode runs outside the attempt window, bounded by the request deadline alone. `--r2-max-concurrent-requests` caps in-flight GETs separately from `--witness-max-concurrent-requests` — the RPC cap sizes a shared gateway, R2 tolerates far more. +**Admission and response-size knobs** (each also settable via its `DEBUG_TRACE_SERVER_*` env var): +- `--admission-max-concurrent`: Requests that may fetch and replay a block at once (default: 640; must be at least 1). +- `--admission-max-queue`: Requests that may wait for a permit on top of those executing (default: 8192; `0` means execute-or-shed). +- `--admission-heavy-max-concurrent`: Concurrent memory-hungry tracer requests (default: 8; sized from memory, not throughput). +- `--admission-disabled`: Kill switch restoring unbounded concurrent work. +- `--max-response-size` / `--max-batch-response-size`: Caps on one reply body and on a whole assembled batch response (defaults: 256MB / 1GB). +- `--admin-addr`: Loopback-only listener for `admin_*` retuning (off unless set). + +`--admission-max-concurrent` + `--admission-max-queue` must be at least `--batch-item-concurrency`, and `--max-batch-response-size` at least `--max-response-size`; both are checked at startup and named in the error. + **Witness routing and sync knobs** (each also settable via its `DEBUG_TRACE_SERVER_*` env var): - `--witness-local-window`: Block-age threshold for the historical witness route (default: 4096; should match the generator's `BACKUP`). - `--witness-old-block-timeout`: Witness-stage budget in seconds for blocks at or below the local tip (defaults to the full `--witness-timeout` budget, tracking it when raised; lower it to fail fast on pruned blocks). diff --git a/bin/debug-trace-server/Cargo.toml b/bin/debug-trace-server/Cargo.toml index 285e15a5..c962a45d 100644 --- a/bin/debug-trace-server/Cargo.toml +++ b/bin/debug-trace-server/Cargo.toml @@ -55,7 +55,7 @@ redb.workspace = true serde.workspace = true serde_json = { workspace = true, features = ["raw_value"] } thiserror.workspace = true -tokio = { workspace = true, features = ["rt", "sync"] } +tokio = { workspace = true, features = ["macros", "net", "rt", "sync", "time"] } tokio-util.workspace = true tower.workspace = true tower-http.workspace = true diff --git a/bin/debug-trace-server/src/admin.rs b/bin/debug-trace-server/src/admin.rs new file mode 100644 index 00000000..30db915f --- /dev/null +++ b/bin/debug-trace-server/src/admin.rs @@ -0,0 +1,343 @@ +//! Loopback-only admin RPC for retuning the admission gate without a restart. +//! +//! # Why a separate listener +//! +//! These setters can throttle request serving to a trickle, and there is no authentication +//! anywhere in this server. Registering them on the customer-facing port would hand every +//! client that can reach us a switch for the gate that is supposed to protect us from them, +//! so the listener is separate, loopback-only (enforced at startup), and off unless asked +//! for. It also carries no RPC middleware: routed through the batch layer, admin traffic +//! would land in the accounting identity's series as `unknown`, and routed through the +//! admission layer, a saturated public port could shed the very call that relieves it. +//! +//! # Why a dedicated runtime +//! +//! EVM tracing runs synchronously inline on the main runtime's worker threads, and tokio +//! cannot preempt a synchronous loop. Enough concurrent traces and no other task on that +//! runtime gets polled — which is precisely the moment an operator reaches for this port. So +//! the admin server gets its own OS thread and its own single-threaded runtime, where +//! nothing traces. This is a workaround for the inline execution, not a fix for it; the fix +//! is a bounded blocking pool for tracing. +//! +//! The method names, parameters and response fields mirror mega-reth's `admin_*` +//! concurrency-limit RPCs, so an operator runbook written for the node works here unchanged. + +use std::{net::SocketAddr, sync::Arc, thread}; + +use eyre::{Result, eyre}; +use jsonrpsee::{ + core::RpcResult, + proc_macros::rpc, + server::{Server, ServerConfig}, + types::{ErrorObjectOwned, error::INVALID_PARAMS_CODE}, +}; +use serde::{Deserialize, Serialize}; +use tracing::{info, warn}; + +use crate::admission::AdmissionLimiter; + +/// A snapshot of the gate: what it is enforcing, and what it currently holds. +#[derive(Debug, Clone, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct ConcurrencyLimitInfo { + /// Requests admitted but not yet holding an execution permit. + pub queued_requests: u64, + /// Requests holding an execution permit. + pub executing_requests: u64, + /// Requests allowed to wait on top of those executing. + pub max_queue_size: u64, + /// Execution permits. + pub max_concurrent: u64, + /// Requests holding a permit from the memory-hungry-tracer sub-cap. + pub heavy_executing_requests: u64, + /// Execution permits reserved for memory-hungry tracers. + pub heavy_max_concurrent: u64, +} + +#[rpc(server, namespace = "admin")] +pub trait AdminRpc { + /// Returns the admission gate's current limits and occupancy. + #[method(name = "getConcurrencyLimit")] + async fn get_concurrency_limit(&self) -> RpcResult; + + /// Updates any subset of the admission limits, returning the resulting state. + /// + /// Lowering a limit below current occupancy aborts nothing — it stops admitting until + /// the excess drains, which is what keeps a retune from being a client-visible incident. + #[method(name = "setConcurrencyLimit")] + async fn set_concurrency_limit( + &self, + max_concurrent: Option, + max_queue_size: Option, + heavy_max_concurrent: Option, + ) -> RpcResult; +} + +/// Serves the admin methods against one limiter. +pub struct AdminApi { + limiter: Arc, + /// Mirrors the startup rule: a gate narrower than one batch's concurrent entries sheds + /// part of every batch on an idle server, so the setter refuses to create that state. + batch_item_concurrency: u64, +} + +impl AdminApi { + fn snapshot(&self) -> ConcurrencyLimitInfo { + ConcurrencyLimitInfo { + queued_requests: self.limiter.queued() as u64, + executing_requests: self.limiter.executing() as u64, + max_queue_size: self.limiter.max_queue(), + max_concurrent: self.limiter.max_concurrent(), + heavy_executing_requests: self.limiter.heavy_executing() as u64, + heavy_max_concurrent: self.limiter.heavy_max_concurrent(), + } + } +} + +fn invalid_params(message: impl Into) -> ErrorObjectOwned { + ErrorObjectOwned::owned(INVALID_PARAMS_CODE, message.into(), None::<()>) +} + +#[jsonrpsee::core::async_trait] +impl AdminRpcServer for AdminApi { + async fn get_concurrency_limit(&self) -> RpcResult { + Ok(self.snapshot()) + } + + async fn set_concurrency_limit( + &self, + max_concurrent: Option, + max_queue_size: Option, + heavy_max_concurrent: Option, + ) -> RpcResult { + // Zero execution permits would park every subsequent request forever with nothing + // left running to release one. Refused rather than clamped: silently substituting a + // different limit than the one asked for is worse than saying no. + if max_concurrent == Some(0) { + return Err(invalid_params( + "maxConcurrent must be at least 1: zero would park every request with nothing \ + running to release a permit", + )); + } + if heavy_max_concurrent == Some(0) { + return Err(invalid_params( + "heavyMaxConcurrent must be at least 1: zero would park every heavy-tracer \ + request with nothing running to release a permit", + )); + } + let resulting_concurrent = max_concurrent.unwrap_or_else(|| self.limiter.max_concurrent()); + let resulting_queue = max_queue_size.unwrap_or_else(|| self.limiter.max_queue()); + let resulting_capacity = resulting_concurrent.saturating_add(resulting_queue); + if resulting_capacity < self.batch_item_concurrency { + return Err(invalid_params(format!( + "maxConcurrent ({resulting_concurrent}) + maxQueueSize ({resulting_queue}) must \ + be at least the batch item concurrency ({}): one batch's entries admit \ + independently, so a smaller gate sheds part of every batch even on an idle \ + server", + self.batch_item_concurrency + ))); + } + + let before = self.snapshot(); + if let Some(permits) = max_concurrent { + self.limiter.set_max_concurrent(permits); + } + if let Some(permits) = max_queue_size { + self.limiter.set_max_queue(permits); + } + if let Some(permits) = heavy_max_concurrent { + self.limiter.set_heavy_max_concurrent(permits); + } + let after = self.snapshot(); + // A production mutation reached over the wire belongs in the log record, with both + // sides of it, so a later shed spike can be attributed to the change that caused it. + info!( + max_concurrent_before = before.max_concurrent, + max_concurrent_after = after.max_concurrent, + max_queue_before = before.max_queue_size, + max_queue_after = after.max_queue_size, + heavy_before = before.heavy_max_concurrent, + heavy_after = after.heavy_max_concurrent, + "Admission limits changed over admin RPC" + ); + Ok(after) + } +} + +/// Starts the admin listener on its own thread and runtime, returning once it is bound. +/// +/// The server is owned by that thread for the process's lifetime, so there is no handle to +/// drop early — dropping a jsonrpsee `ServerHandle` stops its server, and a listener that +/// shuts down the moment it is started is a failure mode worth designing out rather than +/// remembering. +pub(crate) fn spawn( + addr: SocketAddr, + limiter: Arc, + batch_item_concurrency: u64, +) -> Result { + let (tx, rx) = std::sync::mpsc::channel(); + thread::Builder::new() + .name("dts-admin".to_owned()) + .spawn(move || { + let runtime = match tokio::runtime::Builder::new_current_thread().enable_all().build() { + Ok(runtime) => runtime, + Err(e) => { + let _ = tx.send(Err(eyre!("failed to build the admin runtime: {e}"))); + return; + } + }; + runtime.block_on(async move { + // A handful of connections is all an operator or a probe needs, and this port + // is unauthenticated. + let config = ServerConfig::builder().max_connections(8).build(); + let server = match Server::builder().set_config(config).build(addr).await { + Ok(server) => server, + Err(e) => { + let _ = tx.send(Err(eyre!("failed to bind --admin-addr ({addr}): {e}"))); + return; + } + }; + let bound = match server.local_addr() { + Ok(bound) => bound, + Err(e) => { + let _ = tx.send(Err(eyre!("admin listener has no local address: {e}"))); + return; + } + }; + let api = AdminApi { limiter, batch_item_concurrency }; + let handle = server.start(api.into_rpc()); + if tx.send(Ok(bound)).is_err() { + warn!("admin listener started but its caller is gone; shutting it down"); + return; + } + handle.stopped().await; + }); + }) + .map_err(|e| eyre!("failed to spawn the admin listener thread: {e}"))?; + + let bound = + rx.recv().map_err(|_| eyre!("the admin listener thread exited before binding"))??; + info!(admin_addr = %bound, "Admin RPC listening"); + Ok(bound) +} + +#[cfg(test)] +mod tests { + use super::*; + + const BATCH_ITEM_CONCURRENCY: u64 = 16; + + fn api(max_concurrent: u64, max_queue: u64, heavy: u64) -> AdminApi { + AdminApi { + limiter: AdmissionLimiter::new(max_concurrent, max_queue, heavy), + batch_item_concurrency: BATCH_ITEM_CONCURRENCY, + } + } + + fn block_on(f: F) -> F::Output { + tokio::runtime::Builder::new_current_thread().enable_all().build().unwrap().block_on(f) + } + + #[test] + fn get_reports_limits_and_occupancy() { + let api = api(4, 32, 2); + let info = block_on(api.get_concurrency_limit()).expect("get"); + assert_eq!(info.max_concurrent, 4); + assert_eq!(info.max_queue_size, 32); + assert_eq!(info.heavy_max_concurrent, 2); + assert_eq!(info.queued_requests, 0); + assert_eq!(info.executing_requests, 0); + } + + #[test] + fn set_applies_only_the_fields_given() { + let api = api(4, 32, 2); + let info = block_on(api.set_concurrency_limit(Some(9), None, None)).expect("set"); + assert_eq!(info.max_concurrent, 9); + assert_eq!(info.max_queue_size, 32, "an omitted field is left alone"); + assert_eq!(info.heavy_max_concurrent, 2); + assert_eq!(api.limiter.max_concurrent(), 9, "the limiter itself changed"); + } + + /// Zero execution permits would park every subsequent request with nothing left running + /// to release one — a state only a restart recovers from. Refused rather than clamped: + /// quietly enforcing a different limit than the one asked for is its own failure. + #[test] + fn set_rejects_zero_permits() { + let api = api(4, 32, 2); + for (concurrent, heavy) in [(Some(0), None), (None, Some(0))] { + let err = block_on(api.set_concurrency_limit(concurrent, None, heavy)) + .expect_err("zero permits must be refused"); + assert_eq!(err.code(), INVALID_PARAMS_CODE); + } + assert_eq!(api.limiter.max_concurrent(), 4, "a refused write changes nothing"); + assert_eq!(api.limiter.heavy_max_concurrent(), 2); + } + + /// The same rule startup enforces: a gate narrower than one batch's concurrent entries + /// sheds part of every batch even on an idle server, so the setter refuses to create it. + #[test] + fn set_rejects_a_gate_narrower_than_one_batch() { + let api = api(4, 32, 2); + let err = block_on(api.set_concurrency_limit(Some(1), Some(1), None)) + .expect_err("2 total is below the batch item concurrency"); + assert_eq!(err.code(), INVALID_PARAMS_CODE); + assert_eq!(api.limiter.max_concurrent(), 4); + assert_eq!(api.limiter.max_queue(), 32); + + block_on(api.set_concurrency_limit(Some(1), Some(BATCH_ITEM_CONCURRENCY - 1), None)) + .expect("exactly at the floor is allowed"); + } + + /// Lowering a limit below current occupancy must not abort anything — it stops admitting + /// until the excess drains. The opposite would make a routine retune a client-visible + /// incident. + #[test] + fn lowering_a_limit_does_not_abort_in_flight_work() { + let api = api(4, 32, 2); + block_on(async { + let cutoff = std::time::Instant::now() + std::time::Duration::from_secs(30); + let held = api + .limiter + .acquire_execution(crate::metrics::METHOD_TRACE_BLOCK, false, cutoff) + .await + .expect("permit"); + api.set_concurrency_limit(Some(1), None, None).await.expect("set"); + assert_eq!(api.limiter.executing(), 1, "the in-flight request kept its permit"); + drop(held); + }); + } + + /// The listener binds, serves the namespace, and a write over the wire reaches the + /// limiter the request path reads. + #[test] + fn admin_listener_binds_and_serves() { + let limiter = AdmissionLimiter::new(4, 32, 2); + let addr = spawn("127.0.0.1:0".parse().unwrap(), Arc::clone(&limiter), 16) + .expect("the admin listener binds"); + + let post = |body: &str| { + reqwest::blocking::Client::new() + .post(format!("http://{addr}")) + .header("content-type", "application/json") + .body(body.to_owned()) + .send() + .unwrap() + .json::() + .unwrap() + }; + + let got = + post(r#"{"jsonrpc":"2.0","id":1,"method":"admin_getConcurrencyLimit","params":[]}"#); + assert_eq!(got["result"]["maxConcurrent"], serde_json::json!(4)); + assert_eq!(got["result"]["maxQueueSize"], serde_json::json!(32)); + + let set = post( + r#"{"jsonrpc":"2.0","id":2,"method":"admin_setConcurrencyLimit","params":[64,128,3]}"#, + ); + assert_eq!(set["result"]["maxConcurrent"], serde_json::json!(64)); + assert_eq!(limiter.max_concurrent(), 64, "the wire write reached the live limiter"); + assert_eq!(limiter.max_queue(), 128); + assert_eq!(limiter.heavy_max_concurrent(), 3); + } +} diff --git a/bin/debug-trace-server/src/admission.rs b/bin/debug-trace-server/src/admission.rs new file mode 100644 index 00000000..062172c5 --- /dev/null +++ b/bin/debug-trace-server/src/admission.rs @@ -0,0 +1,768 @@ +//! Inbound admission control: the gate that decides, before any work happens, whether a +//! request can be served at all. +//! +//! Every other concurrency bound in this binary is *outbound* — the witness, data and R2 +//! semaphores cap what we ask of someone else, and they are unbounded waits, so overflow +//! can only ever surface as a timeout. Nothing caps what clients ask of us: EVM tracing +//! runs inline on the runtime's worker threads, so enough concurrent requests starve chain +//! sync, the accept loop and the metrics exporter along with each other. This module is the +//! missing half — it turns "too much work offered" into an immediate, typed refusal instead +//! of a slow collapse, which is what makes "may be slow, may reject, must not time out" +//! true rather than aspirational. +//! +//! # Two phases, deliberately in two different places +//! +//! [`AdmissionLayer`] does only the cheap half: a non-blocking compare-and-swap against +//! `max_queue + max_concurrent`, answering [`QUEUE_FULL_CODE`] on the spot when the process +//! is already holding all the work it agreed to hold. The expensive half — waiting for an +//! execution permit — happens in the handler, in [`AdmissionLimiter::acquire_execution`], +//! after the response cache has been consulted. +//! +//! Splitting them is not an aesthetic choice; a single gate in the middleware would break +//! the metrics accounting identity. `CancelGuard` in [`crate::rpc_middleware`] arms on a +//! request's first poll, and today the handler records that request's *arrival* +//! synchronously in that very same poll, before its first `.await`. Arming and arrival are +//! therefore atomic. A middleware gate that parked before the handler would sever that: a +//! client hanging up while queued would record a cancellation with no matching arrival, and +//! `shape = served + errors + cancelled` would drift negative — permanently, and worst +//! under exactly the overload the gate exists for. Because this layer only ever CAS-es, it +//! either sheds inline or falls straight through to the handler in the same poll, and the +//! invariant holds by construction. The permit wait then sits *after* the arrival is +//! already on the books, so a hangup there is a balanced arrival + cancellation for free. +//! +//! Putting the wait in the handler pays three more ways: a response-cache hit returns before +//! a permit is ever requested, so cheap hits are not queued behind cold traces; the tracer +//! identity is already parsed there, so the heavy-shape sub-cap costs nothing rather than +//! requiring a second parse of attacker-controlled JSON at the gate; and what the permits +//! count is blocks actually being fetched and replayed. +//! +//! # Layer order +//! +//! This layer must be installed *inside* `ConcurrentBatchLayer`. That layer never delegates +//! to an inner `batch()` — it decomposes the batch itself and dispatches each entry through +//! `service.call`, so an inner layer sees single calls and every batch entry through one +//! path. Installed outside instead, an N-entry batch would pass the gate as a single unit, +//! which is the same as not gating batches at all — and batches are the traffic shape that +//! has actually taken this server down. It is also what puts the shed inside +//! `track_handler_errors`' task-local scope, which is what keeps `settle_response` +//! unchanged. `batch_entries_are_individually_gated` pins the order. + +use std::{ + future::Future, + sync::{ + Arc, Mutex, + atomic::{AtomicU64, AtomicUsize, Ordering}, + }, + time::Instant, +}; + +use jsonrpsee::server::middleware::rpc::{ + Batch, MethodResponse, Notification, Request, RpcServiceT, +}; +use tokio::sync::{OwnedSemaphorePermit, Semaphore}; +use tower::Layer; + +use crate::metrics::{self, AdmissionMetrics}; + +/// JSON-RPC error code for a request turned away by the gate. +/// +/// Deliberately mega-reth's `ConcurrencyLimiter` code and message verbatim rather than +/// jsonrpsee's `-32009 SERVER_IS_BUSY`: the same gateway fronts both, so a single backpressure +/// code across the fleet means whatever already backs off for the node backs off for us. +pub(crate) const QUEUE_FULL_CODE: i32 = -32013; + +/// The message paired with [`QUEUE_FULL_CODE`], byte-identical to mega-reth's. +pub(crate) const QUEUE_FULL_MESSAGE: &str = "Request queue is full"; + +/// Builds the shed error response body. +fn queue_full_error() -> jsonrpsee::types::ErrorObjectOwned { + jsonrpsee::types::ErrorObjectOwned::owned(QUEUE_FULL_CODE, QUEUE_FULL_MESSAGE, None::<()>) +} + +/// A permit count that can be raised and lowered while requests are in flight, without +/// giving up FIFO fairness. +/// +/// The obvious alternative — a hand-rolled counter plus [`tokio::sync::Notify`], which is +/// what the mega-reth limiter this design otherwise mirrors uses — has two failure modes +/// worth not inheriting. `Notify::notify_waiters` wakes every waiter to race for one slot, +/// which is O(waiters²) wakeups to drain a queue and offers no ordering, so a request can +/// lose every race indefinitely; and a `Notified` only receives broadcasts issued after it +/// is *created*, so checking capacity before creating one parks a request until some +/// unrelated request happens to finish. A semaphore has neither problem. +/// +/// What a semaphore lacks is shrinking: `forget_permits` can only remove permits that are +/// currently available, and reports how many it managed. The shortfall is recorded as +/// `debt` and settled lazily — a permit released while a debt is outstanding is forgotten +/// instead of returned. So a shrink takes effect as soon as it can and never blocks, and +/// the limit is honoured from the next release onward. +#[derive(Debug)] +struct ResizableSemaphore { + sem: Arc, + /// The configured limit — authoritative for reporting, and reached by the semaphore + /// itself once any outstanding `debt` is settled. + limit: AtomicU64, + /// Permits a shrink could not remove because they were checked out at the time. + debt: AtomicU64, + /// Permits currently handed out. + /// + /// Tracked rather than derived as `limit - available`: once a shrink leaves debt behind + /// that difference stops being the number of holders and becomes the *new* limit, which is + /// exactly backwards — the reason the shrink left debt is that the old holders are all + /// still running. Reporting the new limit as occupancy would tell an operator their retune + /// had already taken effect while every one of those requests was still resident. + checked_out: AtomicUsize, + /// Serializes resizes against each other. Never taken on the acquire/release path. + resize: Mutex<()>, +} + +impl ResizableSemaphore { + fn new(permits: u64) -> Self { + let permits = clamp_permits(permits); + Self { + sem: Arc::new(Semaphore::new(permits as usize)), + limit: AtomicU64::new(permits), + debt: AtomicU64::new(0), + checked_out: AtomicUsize::new(0), + resize: Mutex::new(()), + } + } + + fn limit(&self) -> u64 { + self.limit.load(Ordering::Relaxed) + } + + /// Applies a new limit, growing immediately and shrinking as far as free permits allow. + fn set_limit(&self, permits: u64) { + let permits = clamp_permits(permits); + let _resize = self.resize.lock().unwrap_or_else(|e| e.into_inner()); + let previous = self.limit.swap(permits, Ordering::SeqCst); + if permits > previous { + // Cancel outstanding debt first: those permits were already removed from the + // budget on paper but not yet from the semaphore, so re-adding them here as + // well would double-count the growth. + let growth = permits - previous; + let cancelled = self.cancel_debt(growth); + if growth > cancelled { + self.sem.add_permits((growth - cancelled) as usize); + } + } else if permits < previous { + let wanted = (previous - permits) as usize; + let removed = self.sem.forget_permits(wanted); + if removed < wanted { + self.debt.fetch_add((wanted - removed) as u64, Ordering::SeqCst); + } + } + } + + /// Cancels up to `max` of the outstanding debt, returning how much was cancelled. + fn cancel_debt(&self, max: u64) -> u64 { + let mut current = self.debt.load(Ordering::SeqCst); + loop { + if current == 0 || max == 0 { + return 0; + } + let take = current.min(max); + match self.debt.compare_exchange_weak( + current, + current - take, + Ordering::SeqCst, + Ordering::SeqCst, + ) { + Ok(_) => return take, + Err(actual) => current = actual, + } + } + } + + /// Whether a permit being released should be forgotten rather than returned. + fn settle_on_release(&self) -> bool { + self.cancel_debt(1) == 1 + } + + /// Permits currently handed out. + fn checked_out(&self) -> usize { + self.checked_out.load(Ordering::Relaxed) + } +} + +/// Tokio panics past this, and the admin RPC takes operator input. +fn clamp_permits(permits: u64) -> u64 { + permits.clamp(1, Semaphore::MAX_PERMITS as u64) +} + +/// A checked-out permit that honours any pending shrink when it is released. +#[derive(Debug)] +struct DebtAwarePermit { + permit: Option, + owner: Arc, +} + +impl Drop for DebtAwarePermit { + fn drop(&mut self) { + if let Some(permit) = self.permit.take() { + self.owner.checked_out.fetch_sub(1, Ordering::Release); + if self.owner.settle_on_release() { + permit.forget(); + } + } + } +} + +/// How much of the process's memory budget a request's tracer is expected to want. +/// +/// The distinction exists because one execution budget cannot serve both: sized for the +/// `callTracer` traffic that has been measured clean it admits hundreds of concurrent +/// blocks, and hundreds of concurrent `prestateTracer` traces over large blocks is the +/// shape that has already OOM-killed this server once. [`TraceWeight::Heavy`] requests pass +/// a second, much smaller budget first, so the worst-case resident set is a number an +/// operator can compute rather than a property of what clients happen to ask for. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum TraceWeight { + /// Bounded output per transaction; the request's cost is dominated by the fetch. + Normal, + /// Output can run to hundreds of megabytes on a large block. + Heavy, +} + +impl TraceWeight { + /// Whether this request must pass the heavy sub-cap. + pub(crate) fn is_heavy(self) -> bool { + matches!(self, Self::Heavy) + } +} + +/// Why a request could not obtain an execution permit. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum AdmissionError { + /// The wait would have left too little of the request's budget for the work itself. + Overloaded, +} + +/// The process-wide inbound gate. +pub(crate) struct AdmissionLimiter { + /// Admitted and unfinished: queued plus executing. + in_flight: AtomicUsize, + /// How many admitted requests may be waiting on top of the executing ones. + max_queue: AtomicU64, + /// Execution permits — one per block being fetched and replayed. + execution: Arc, + /// A smaller budget the memory-hungry tracer shapes must pass first. + heavy: Arc, +} + +impl AdmissionLimiter { + /// Builds a limiter. Every value is clamped to at least 1 permit; `max_queue` may be 0, + /// which means "execute or shed, never wait". + pub(crate) fn new(max_concurrent: u64, max_queue: u64, heavy_max_concurrent: u64) -> Arc { + let limiter = Arc::new(Self { + in_flight: AtomicUsize::new(0), + max_queue: AtomicU64::new(max_queue), + execution: Arc::new(ResizableSemaphore::new(max_concurrent)), + heavy: Arc::new(ResizableSemaphore::new(heavy_max_concurrent)), + }); + limiter.publish_limits(); + limiter + } + + /// Total requests that may be admitted at once. + /// + /// `saturating_add` because both terms are operator input: a `u64::MAX` "unlimited" + /// sentinel that wrapped here would make the gate shed *everything*. + fn capacity(&self) -> u64 { + self.max_queue.load(Ordering::Relaxed).saturating_add(self.execution.limit()) + } + + pub(crate) fn max_concurrent(&self) -> u64 { + self.execution.limit() + } + + pub(crate) fn max_queue(&self) -> u64 { + self.max_queue.load(Ordering::Relaxed) + } + + pub(crate) fn heavy_max_concurrent(&self) -> u64 { + self.heavy.limit() + } + + pub(crate) fn in_flight(&self) -> usize { + self.in_flight.load(Ordering::Relaxed) + } + + /// Requests holding an execution permit. + pub(crate) fn executing(&self) -> usize { + self.execution.checked_out() + } + + /// Requests holding a permit from the heavy-tracer sub-cap. + pub(crate) fn heavy_executing(&self) -> usize { + self.heavy.checked_out() + } + + /// Requests admitted but not yet executing. + pub(crate) fn queued(&self) -> usize { + self.in_flight().saturating_sub(self.executing()) + } + + pub(crate) fn set_max_concurrent(&self, permits: u64) { + self.execution.set_limit(permits); + self.publish_limits(); + } + + pub(crate) fn set_max_queue(&self, permits: u64) { + self.max_queue.store(permits, Ordering::Relaxed); + self.publish_limits(); + } + + pub(crate) fn set_heavy_max_concurrent(&self, permits: u64) { + self.heavy.set_limit(permits); + self.publish_limits(); + } + + fn publish_limits(&self) { + metrics::record_admission_limits( + self.max_concurrent(), + self.max_queue(), + self.heavy_max_concurrent(), + ); + } + + /// The whole admission decision, made without blocking and without touching the handler. + /// + /// `None` means shed. This is the "can this request be served at all" question answered + /// before any parsing, fetching or tracing happens. + fn try_admit(self: &Arc, method: &'static str) -> Option { + let capacity = self.capacity(); + let mut current = self.in_flight.load(Ordering::Relaxed); + loop { + if current as u64 >= capacity { + return None; + } + match self.in_flight.compare_exchange_weak( + current, + current + 1, + Ordering::Acquire, + Ordering::Relaxed, + ) { + Ok(_) => { + let gauges = AdmissionMetrics::new_for_method(method); + gauges.in_flight_delta(1.0); + return Some(InFlightGuard { limiter: Arc::clone(self), gauges }); + } + Err(actual) => current = actual, + } + } + } + + /// Waits for the permits this request needs to fetch and replay a block. + /// + /// `cutoff` is the instant past which starting the work would be pointless — the caller + /// derives it from its own deadline, so a request that has queued away the budget its + /// witness fetch still needs is refused now rather than started and timed out later. + /// That refusal is the difference between "may reject" and "times out". + /// + /// A heavy shape takes the sub-cap permit *first*. Acquiring it second would let heavy + /// requests occupy execution permits while waiting for each other, starving ordinary + /// traffic behind work that is not running. + pub(crate) async fn acquire_execution( + self: &Arc, + method: &'static str, + heavy: bool, + cutoff: Instant, + ) -> Result { + let started = Instant::now(); + let heavy_permit = if heavy { Some(acquire_by(&self.heavy, cutoff).await?) } else { None }; + let permit = acquire_by(&self.execution, cutoff).await?; + metrics::record_admission_permit_wait(started.elapsed().as_secs_f64()); + + let gauges = AdmissionMetrics::new_for_method(method); + gauges.executing_delta(1.0); + if heavy_permit.is_some() { + metrics::record_admission_heavy_delta(1.0); + } + Ok(ExecutionPermit { _permit: permit, heavy: heavy_permit, gauges }) + } +} + +/// Acquires one permit, giving up at `cutoff`. +async fn acquire_by( + semaphore: &Arc, + cutoff: Instant, +) -> Result { + let sem = Arc::clone(&semaphore.sem); + let permit = tokio::time::timeout_at(cutoff.into(), sem.acquire_owned()) + .await + .map_err(|_| AdmissionError::Overloaded)? + // The semaphore is never closed for the process's lifetime. + .map_err(|_| AdmissionError::Overloaded)?; + semaphore.checked_out.fetch_add(1, Ordering::Acquire); + Ok(DebtAwarePermit { permit: Some(permit), owner: Arc::clone(semaphore) }) +} + +/// Holds one unit of admitted capacity for the whole request. +pub(crate) struct InFlightGuard { + limiter: Arc, + gauges: AdmissionMetrics, +} + +impl Drop for InFlightGuard { + fn drop(&mut self) { + self.limiter.in_flight.fetch_sub(1, Ordering::Release); + self.gauges.in_flight_delta(-1.0); + } +} + +/// Holds the right to fetch and replay one block. +#[derive(Debug)] +pub(crate) struct ExecutionPermit { + _permit: DebtAwarePermit, + heavy: Option, + gauges: AdmissionMetrics, +} + +impl Drop for ExecutionPermit { + fn drop(&mut self) { + self.gauges.executing_delta(-1.0); + if self.heavy.is_some() { + metrics::record_admission_heavy_delta(-1.0); + } + } +} + +/// Tower layer installing [`AdmissionService`] around the RPC service. +#[derive(Clone)] +pub(crate) struct AdmissionLayer { + limiter: Arc, +} + +impl AdmissionLayer { + pub(crate) fn new(limiter: Arc) -> Self { + Self { limiter } + } +} + +impl Layer for AdmissionLayer { + type Service = AdmissionService; + + fn layer(&self, service: S) -> Self::Service { + AdmissionService { service, limiter: Arc::clone(&self.limiter) } + } +} + +/// Sheds calls the process has no capacity for; passes everything else through untouched. +#[derive(Clone)] +pub(crate) struct AdmissionService { + service: S, + limiter: Arc, +} + +impl RpcServiceT for AdmissionService +where + S: RpcServiceT + Clone + Send + Sync + 'static, +{ + type MethodResponse = MethodResponse; + type NotificationResponse = S::NotificationResponse; + type BatchResponse = S::BatchResponse; + + fn call<'a>( + &self, + request: Request<'a>, + ) -> impl Future + Send + 'a { + let method = metrics::method_label(request.method_name()); + let gated = metrics::is_gated(method); + let service = self.service.clone(); + let limiter = Arc::clone(&self.limiter); + // Everything that decides an outcome runs inside this block, never in the prefix + // above: `record_admission_shed` reaches for the `ERROR_SELF_REPORTED` task-local + // that tells the batch layer's fallback this `-32013` is already accounted for, and + // that scope only exists once the future is being polled. Recorded from the prefix, + // every shed would double-count its error and false-fire the `unattributed` alarm. + async move { + if !gated { + return service.call(request).await; + } + let Some(guard) = limiter.try_admit(method) else { + metrics::record_admission_shed(method); + let id = request.id.clone(); + return MethodResponse::error(id, queue_full_error()) + .with_extensions(request.extensions); + }; + let response = service.call(request).await; + drop(guard); + response + } + } + + fn notification<'a>( + &self, + n: Notification<'a>, + ) -> impl Future + Send + 'a { + // jsonrpsee answers notifications without ever dispatching a handler, so there is + // no work here to protect and nothing to shed. + self.service.notification(n) + } + + fn batch<'a>(&self, batch: Batch<'a>) -> impl Future + Send + 'a { + // Unreachable in this server: `ConcurrentBatch` sits outside and decomposes batches + // into per-entry `call`s rather than delegating here. Kept as a pass-through so the + // layer stays correct if it is ever installed on its own. + self.service.batch(batch) + } +} + +#[cfg(test)] +mod tests { + use std::time::Duration; + + use super::*; + use crate::metrics::METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER; + + const METHOD: &str = METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER; + + /// A cutoff far enough away that a test never trips the deadline clamp by accident. + fn far() -> Instant { + Instant::now() + Duration::from_secs(30) + } + + #[test] + fn admits_exactly_queue_plus_concurrent() { + let limiter = AdmissionLimiter::new(2, 3, 1); + let admitted: Vec<_> = (0..5).map(|_| limiter.try_admit(METHOD)).collect(); + assert!(admitted.iter().all(|guard| guard.is_some()), "the first five must be admitted"); + assert!(limiter.try_admit(METHOD).is_none(), "the sixth is past capacity"); + assert_eq!(limiter.in_flight(), 5); + + drop(admitted); + assert_eq!(limiter.in_flight(), 0, "every guard returns its unit"); + assert!(limiter.try_admit(METHOD).is_some(), "capacity is available again"); + } + + /// `u64::MAX` is the shape of an "unlimited" sentinel an operator might reach for. If the + /// capacity sum wrapped, the gate would shed *everything* — the exact inverse of intent. + #[test] + fn capacity_saturates_instead_of_wrapping() { + let limiter = AdmissionLimiter::new(u64::MAX, u64::MAX, 1); + assert_eq!(limiter.capacity(), u64::MAX); + assert!(limiter.try_admit(METHOD).is_some()); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn queue_is_zero_means_execute_or_shed() { + let limiter = AdmissionLimiter::new(1, 0, 1); + let _first = limiter.try_admit(METHOD).expect("the one execution slot is admissible"); + assert!(limiter.try_admit(METHOD).is_none(), "with no queue there is nowhere to wait"); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn heavy_requests_pass_both_budgets() { + let limiter = AdmissionLimiter::new(8, 8, 1); + let heavy = limiter.acquire_execution(METHOD, true, far()).await.expect("first heavy"); + assert_eq!(limiter.executing(), 1); + + // The sub-cap is full, so a second heavy request waits even though seven ordinary + // execution permits are free. + let blocked = limiter.acquire_execution(METHOD, true, Instant::now()).await; + assert_eq!(blocked.unwrap_err(), AdmissionError::Overloaded); + + // An ordinary request is unaffected by the heavy sub-cap. + let _normal = limiter.acquire_execution(METHOD, false, far()).await.expect("normal"); + drop(heavy); + limiter.acquire_execution(METHOD, true, far()).await.expect("sub-cap freed"); + } + + /// A request that queued past the point where its remaining budget could still cover the + /// work is refused rather than started — the difference between "may reject" and "times + /// out", which is the whole reason the cutoff is threaded in. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn permit_wait_gives_up_at_the_cutoff() { + let limiter = AdmissionLimiter::new(1, 8, 1); + let _held = limiter.acquire_execution(METHOD, false, far()).await.expect("first"); + + let started = Instant::now(); + let refused = limiter + .acquire_execution(METHOD, false, Instant::now() + Duration::from_millis(50)) + .await; + assert_eq!(refused.unwrap_err(), AdmissionError::Overloaded); + assert!(started.elapsed() < Duration::from_secs(5), "it gave up, it did not hang"); + } + + /// Regression for the reference implementation's lost wakeup: it created its wait future + /// *after* checking capacity, so a permit released in that window was never observed and + /// the request parked until some unrelated request happened to finish. The failure mode is + /// a hang, not an assertion, so the whole loop runs under a timeout. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn a_permit_freed_while_waiting_is_never_lost() { + let limiter = AdmissionLimiter::new(1, 64, 1); + let churn = async { + let mut tasks = tokio::task::JoinSet::new(); + for _ in 0..4 { + let limiter = Arc::clone(&limiter); + tasks.spawn(async move { + for _ in 0..250 { + let permit = + limiter.acquire_execution(METHOD, false, far()).await.expect("permit"); + drop(permit); + tokio::task::yield_now().await; + } + }); + } + while let Some(joined) = tasks.join_next().await { + joined.expect("no task panicked"); + } + }; + tokio::time::timeout(Duration::from_secs(30), churn) + .await + .expect("a freed permit was lost and the waiters parked forever"); + } + + /// Regression for the reference implementation's other bug: raising a limit there only + /// stored the new value, so parked waiters learned about the extra capacity at the next + /// completion — and never, if nothing was running. Note the holder is deliberately *not* + /// released; the raise alone must be enough. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn raising_the_limit_wakes_parked_waiters() { + let limiter = AdmissionLimiter::new(1, 64, 1); + let _held = limiter.acquire_execution(METHOD, false, far()).await.expect("first"); + + let mut waiters = tokio::task::JoinSet::new(); + for _ in 0..4 { + let limiter = Arc::clone(&limiter); + waiters.spawn(async move { limiter.acquire_execution(METHOD, false, far()).await }); + } + // Let them all reach the wait before the capacity appears. + tokio::time::sleep(Duration::from_millis(50)).await; + limiter.set_max_concurrent(8); + + let woken = async { + let mut permits = Vec::new(); + while let Some(joined) = waiters.join_next().await { + permits.push(joined.expect("no panic").expect("permit")); + } + permits + }; + let permits = tokio::time::timeout(Duration::from_secs(10), woken) + .await + .expect("raising the limit did not wake the parked waiters"); + assert_eq!(permits.len(), 4); + } + + /// Shrinking cannot revoke a permit that is already checked out, so the shortfall is + /// carried as debt and settled by the next releases. Verified through behaviour: after the + /// shrink the limiter must never hand out more than the new limit at once. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn shrinking_below_checked_out_permits_settles_on_release() { + let limiter = AdmissionLimiter::new(4, 64, 1); + let held: Vec<_> = { + let mut held = Vec::new(); + for _ in 0..4 { + held.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); + } + held + }; + assert_eq!(limiter.executing(), 4); + + limiter.set_max_concurrent(1); + assert_eq!(limiter.max_concurrent(), 1, "the configured limit applies immediately"); + + // Releasing three must not make three permits available again: they pay off the debt. + drop(held); + let _one = limiter.acquire_execution(METHOD, false, far()).await.expect("the one permit"); + let second = limiter + .acquire_execution(METHOD, false, Instant::now() + Duration::from_millis(50)) + .await; + assert_eq!( + second.unwrap_err(), + AdmissionError::Overloaded, + "the shrink was honoured once the permits came back" + ); + } + + /// Occupancy stays truthful while a shrink's debt is outstanding. + /// + /// The regression this pins: deriving `executing()` as `limit - available_permits` reports + /// the *new* limit once a shrink cannot remove permits that are checked out — so an + /// operator shrinking 4 to 1 under load would be told 1 request was executing and 3 were + /// queued, when in truth 4 were still executing and nothing was queued. That is the + /// read-back of the very write they just made, wrong in both directions, during exactly + /// the incident it exists to inform. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn occupancy_stays_truthful_while_a_shrink_is_outstanding() { + let limiter = AdmissionLimiter::new(4, 64, 4); + let mut admitted = Vec::new(); + let mut held = Vec::new(); + for _ in 0..4 { + admitted.push(limiter.try_admit(METHOD).expect("admit")); + held.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); + } + assert_eq!(limiter.executing(), 4); + + limiter.set_max_concurrent(1); + assert_eq!(limiter.max_concurrent(), 1, "the configured limit applies at once"); + assert_eq!(limiter.executing(), 4, "but all four holders are still running"); + assert_eq!(limiter.queued(), 0, "and none of them is waiting for anything"); + + held.pop(); + assert_eq!(limiter.executing(), 3, "occupancy tracks releases through the debt"); + held.clear(); + assert_eq!(limiter.executing(), 0); + } + + /// The heavy sub-cap reports its own occupancy, so the admin snapshot can distinguish + /// "saturated on memory-hungry tracers" from "saturated overall". + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn heavy_occupancy_is_reported_separately() { + let limiter = AdmissionLimiter::new(8, 8, 2); + let _heavy = limiter.acquire_execution(METHOD, true, far()).await.expect("heavy"); + let _normal = limiter.acquire_execution(METHOD, false, far()).await.expect("normal"); + assert_eq!(limiter.executing(), 2, "both hold an ordinary execution permit"); + assert_eq!(limiter.heavy_executing(), 1, "only one holds a heavy permit"); + } + + /// A heavy request that wins the sub-cap but loses the ordinary permit must not keep the + /// scarcer of the two. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn a_heavy_request_that_times_out_releases_its_sub_cap_permit() { + let limiter = AdmissionLimiter::new(1, 8, 1); + let _blocker = limiter.acquire_execution(METHOD, false, far()).await.expect("blocker"); + + let refused = limiter + .acquire_execution(METHOD, true, Instant::now() + Duration::from_millis(50)) + .await; + assert_eq!(refused.unwrap_err(), AdmissionError::Overloaded); + assert_eq!( + limiter.heavy_executing(), + 0, + "the sub-cap permit was released when the ordinary one could not be had" + ); + } + + /// Growing again after a shrink that left debt must not double-count: the growth first + /// cancels the outstanding debt, and only the remainder becomes new permits. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn growing_cancels_outstanding_debt_first() { + let limiter = AdmissionLimiter::new(4, 64, 1); + let mut held = Vec::new(); + for _ in 0..4 { + held.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); + } + limiter.set_max_concurrent(1); // 4 checked out, 3 of debt + limiter.set_max_concurrent(4); // back where we started; debt must simply vanish + drop(held); + + let mut regained = Vec::new(); + for _ in 0..4 { + regained.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); + } + assert_eq!(limiter.executing(), 4, "all four permits came back, none forgotten twice"); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn queued_is_in_flight_minus_executing() { + let limiter = AdmissionLimiter::new(1, 4, 1); + let _admitted: Vec<_> = (0..3).map(|_| limiter.try_admit(METHOD).expect("admit")).collect(); + assert_eq!(limiter.queued(), 3, "admitted, none executing yet"); + + let _permit = limiter.acquire_execution(METHOD, false, far()).await.expect("permit"); + assert_eq!(limiter.executing(), 1); + assert_eq!(limiter.queued(), 2); + } +} diff --git a/bin/debug-trace-server/src/data_provider.rs b/bin/debug-trace-server/src/data_provider.rs index 4fbd3f8e..425d12e1 100644 --- a/bin/debug-trace-server/src/data_provider.rs +++ b/bin/debug-trace-server/src/data_provider.rs @@ -540,6 +540,37 @@ impl DataProvider { Instant::now() + self.block_fetch_timeout } + /// The instant past which waiting for an inbound execution permit stops being useful. + /// + /// A request that queues past this has spent the budget its witness stage still needs, so + /// letting it start would only trade a rejection for a deadline error — which is the + /// outcome the admission gate exists to prevent. Derived from the two configured budgets + /// rather than being its own knob, so it tracks whatever they are set to. + /// + /// The reserve normally *is* the witness budget, but falls back to half the request's + /// budget when the witness timeout does not fit inside it. `--witness-timeout` may legally + /// be set at or above `--block-fetch-timeout` — the witness sub-deadline is a `min` against + /// the outer one, so a larger value simply never binds — and reserving all of it would + /// leave a permit wait of zero, silently turning `--admission-max-queue` into a no-op: the + /// server would shed hard at exactly `max_concurrent` while the permit-wait histogram read + /// zero, pointing an operator at client load rather than at their own timeout setting. + /// Half is the share the witness stage already reserves for its own fallbacks. + pub(crate) fn permit_cutoff(&self, deadline: Instant) -> Instant { + deadline.checked_sub(self.permit_reserve()).unwrap_or_else(Instant::now) + } + + /// The share of a request's budget held back from the admission queue for the work itself. + fn permit_reserve(&self) -> Duration { + let witness = self.witness_cfg.witness_timeout; + if witness < self.block_fetch_timeout { witness } else { self.block_fetch_timeout / 2 } + } + + /// The longest a request may wait for an execution permit under the configured budgets — + /// published at startup so an operator can see what `--admission-max-queue` actually buys. + pub(crate) fn max_permit_wait(&self) -> Duration { + self.block_fetch_timeout.saturating_sub(self.permit_reserve()) + } + /// Resolves a block number to its canonical block hash. /// /// This is what makes number-keyed requests safe to serve from the hash-keyed response @@ -635,8 +666,9 @@ impl DataProvider { pub async fn get_block_data_by_hash( &self, block_hash: B256, + deadline: Instant, ) -> DataProviderResult> { - self.get_block_data(block_hash, None, self.fetch_deadline()).await + self.get_block_data(block_hash, None, deadline).await } /// Tiered block-data lookup: memory cache → local DB → single-flight RPC fetch, all @@ -734,9 +766,9 @@ impl DataProvider { pub async fn get_block_data_for_tx( &self, tx_hash: B256, + deadline: Instant, ) -> DataProviderResult<(Arc, usize)> { trace!(tx_hash = %tx_hash, "Looking up transaction"); - let deadline = self.fetch_deadline(); // Fetch the transaction to find its block. The outer result is `Err(Deadline)`; the // inner is `Err` for "tx exists but has no block_hash" (pending) — classify explicitly @@ -1823,6 +1855,52 @@ mod tests { ) } + /// The admission queue keeps a usable share of the budget under any legal timeout pair. + /// + /// `--witness-timeout` may legally be set at or above `--block-fetch-timeout` — the witness + /// sub-deadline is a `min` against the outer one, so a larger value simply never binds. A + /// reserve of the raw witness timeout would then swallow the whole budget and leave a + /// permit wait of zero, silently reducing `--admission-max-queue` to a no-op: the server + /// would shed hard at exactly `max_concurrent` while the permit-wait histogram read zero, + /// pointing an operator at client load rather than at their own timeout setting. + #[test] + fn permit_reserve_never_swallows_the_whole_budget() { + let reserve = |witness_secs: u64, fetch_secs: u64| { + let provider = DataProvider::new( + Arc::new( + RpcClient::new_with_config( + &["http://127.0.0.1:1"], + &["http://127.0.0.1:1"], + RpcClientConfig::trace_server(), + None, + ) + .unwrap(), + ), + None, + None, + test_support::noop_contract_cache(), + WitnessFetchConfig::with_defaults(witness_secs), + Duration::from_secs(fetch_secs), + 1024, + ); + (provider.max_permit_wait(), provider.permit_cutoff(provider.fetch_deadline())) + }; + + // The ordinary case: the witness stage keeps its full budget, the queue gets the rest. + let (wait, cutoff) = reserve(8, 13); + assert_eq!(wait, Duration::from_secs(5), "13s budget less the 8s witness reserve"); + assert!(cutoff > Instant::now(), "a request may still wait"); + + // The inverted case: the reserve is capped at half, so the queue keeps the other half. + let (wait, cutoff) = reserve(20, 13); + assert_eq!(wait, Duration::from_secs(13) - Duration::from_secs(13) / 2); + assert!(cutoff > Instant::now(), "the queue is still usable, not silently inert"); + + // Equal budgets are the boundary of the old behaviour and must stay usable too. + let (wait, _) = reserve(13, 13); + assert_eq!(wait, Duration::from_secs(13) / 2); + } + /// [`provider_with_tiers`] with no memory cache and an empty noop-backed contract /// cache. fn provider_with(url: &str, db: Option>) -> DataProvider { @@ -1849,8 +1927,14 @@ mod tests { contract_cache, ); - let first = provider.get_block_data_by_hash(hash).await.expect("db-served fetch"); - let second = provider.get_block_data_by_hash(hash).await.expect("memory-served fetch"); + let first = provider + .get_block_data_by_hash(hash, provider.fetch_deadline()) + .await + .expect("db-served fetch"); + let second = provider + .get_block_data_by_hash(hash, provider.fetch_deadline()) + .await + .expect("memory-served fetch"); assert_eq!( store.block_reads.load(Ordering::Relaxed), @@ -1878,7 +1962,10 @@ mod tests { provider_with_tiers(&test_support::hanging_url(), None, Some(cache), contract_cache); let start = std::time::Instant::now(); - let data = provider.get_block_data_by_hash(hash).await.expect("memory hit"); + let data = provider + .get_block_data_by_hash(hash, provider.fetch_deadline()) + .await + .expect("memory hit"); assert!( start.elapsed() < Duration::from_millis(500), "memory hit must not reach the hanging upstream" @@ -1900,8 +1987,14 @@ mod tests { contract_cache, ); - provider.get_block_data_by_hash(hash).await.expect("first db read"); - provider.get_block_data_by_hash(hash).await.expect("second db read"); + provider + .get_block_data_by_hash(hash, provider.fetch_deadline()) + .await + .expect("first db read"); + provider + .get_block_data_by_hash(hash, provider.fetch_deadline()) + .await + .expect("second db read"); assert_eq!(store.block_reads.load(Ordering::Relaxed), 2); } @@ -2616,7 +2709,9 @@ mod tests { let provider = provider_at(&url, None); let start = std::time::Instant::now(); - let result = provider.get_block_data_by_hash(B256::from([0x42; 32])).await; + let result = provider + .get_block_data_by_hash(B256::from([0x42; 32]), provider.fetch_deadline()) + .await; let elapsed = start.elapsed(); let err = match result { @@ -2923,7 +3018,9 @@ mod tests { let block_hash = B256::from([0xAB; 32]); let handle = { let provider = Arc::clone(&provider); - tokio::spawn(async move { provider.get_block_data_by_hash(block_hash).await }) + tokio::spawn(async move { + provider.get_block_data_by_hash(block_hash, provider.fetch_deadline()).await + }) }; // Give the spawned task enough scheduling turns to reach `shared.await` and register diff --git a/bin/debug-trace-server/src/main.rs b/bin/debug-trace-server/src/main.rs index e3dbf9c8..3a6854ec 100644 --- a/bin/debug-trace-server/src/main.rs +++ b/bin/debug-trace-server/src/main.rs @@ -45,6 +45,7 @@ //! - **Local cache mode**: With `data_dir`, enables chain sync to pre-fetch blocks into local DB use std::{ + net::SocketAddr, path::{Path, PathBuf}, sync::Arc, }; @@ -68,6 +69,8 @@ use tokio::task; use tokio_util::sync::CancellationToken; use tracing::{debug, error, info, instrument, warn}; +mod admin; +mod admission; mod block_data_cache; mod body_metrics; mod chain_sync; @@ -85,6 +88,7 @@ mod server_db; mod timing; mod tracing_executor; +use admission::AdmissionLimiter; use block_data_cache::{ BLOCK_DATA_CACHE_SHARDS, BlockDataCache, DEFAULT_BLOCK_DATA_CACHE_MAX_BYTES, }; @@ -218,6 +222,102 @@ struct Args { )] batch_item_concurrency: u32, + /// Requests that may be fetching and replaying a block at once. + /// + /// This is the process's real work budget: every other concurrency knob here caps what + /// we ask of someone else. Sizing is not a core count — only about 2% of a trace + /// request is CPU, the rest is waiting on the upstream node and R2 — so derive it from + /// measured service time instead: `throughput x mean_handler_seconds`. The default sits + /// just above the highest occupancy this server has been measured serving cleanly, so it + /// bounds a previously unbounded process without throttling a known-good workload. + /// + /// A response-cache hit never takes one of these. + #[clap( + long, + env = "DEBUG_TRACE_SERVER_ADMISSION_MAX_CONCURRENT", + default_value_t = DEFAULT_ADMISSION_MAX_CONCURRENT, + value_parser = clap::value_parser!(u64).range(1..), + )] + admission_max_concurrent: u64, + + /// Requests that may wait for an execution permit on top of those holding one. + /// + /// A latency knob, not a memory one: queue depth divided by the service rate is how long + /// a request waits, so `queue = rate x acceptable_wait`. At 1000 blocks/s a 1000-deep + /// queue is one second of waiting. `0` means execute-or-shed with no waiting at all. + /// Beyond `max_concurrent + max_queue` admitted requests, arrivals are refused + /// immediately with `-32013` rather than queued indefinitely. + #[clap( + long, + env = "DEBUG_TRACE_SERVER_ADMISSION_MAX_QUEUE", + default_value_t = DEFAULT_ADMISSION_MAX_QUEUE, + )] + admission_max_queue: u64, + + /// Requests running a memory-hungry tracer that may execute at once, on top of needing + /// an ordinary execution permit. + /// + /// `prestateTracer`, JS tracers, `muxTracer` and struct-logger requests with non-default + /// flags can each produce hundreds of megabytes from one large block — a single such + /// response has been measured at over 900 MB. This sub-cap, multiplied by + /// `--max-response-size`, is what makes the process's worst-case resident set a number + /// an operator can compute; size it from available memory, not from throughput. + #[clap( + long, + env = "DEBUG_TRACE_SERVER_ADMISSION_HEAVY_MAX_CONCURRENT", + default_value_t = DEFAULT_ADMISSION_HEAVY_MAX_CONCURRENT, + value_parser = clap::value_parser!(u64).range(1..), + )] + admission_heavy_max_concurrent: u64, + + /// Disables inbound admission control entirely (kill switch). + /// + /// Restores the pre-gate behaviour: every request executes immediately and the process + /// accepts unbounded concurrent work. + #[clap(long, env = "DEBUG_TRACE_SERVER_ADMISSION_DISABLED")] + admission_disabled: bool, + + /// Maximum serialized size of a single RPC response body. + /// + /// Checked where this server serializes the reply, so an over-limit body is discarded + /// before it can be copied again into the JSON-RPC envelope and, for a batch, retained + /// there until every entry finishes — that accumulation, not any single response, is what + /// has previously exhausted memory on this server. Over-limit responses are answered with + /// an error and counted on `debug_trace_response_oversized_total`. + #[clap( + long, + env = "DEBUG_TRACE_SERVER_MAX_RESPONSE_SIZE", + default_value = "256MB", + value_parser = parse_size, + )] + max_response_size: u64, + + /// Maximum assembled size of one JSON-RPC batch response. + /// + /// A different bound from `--max-response-size`, because it bounds a different thing: the + /// batch builder retains every completed entry's body until the whole batch finishes, so a + /// batch's memory is the *sum* of its entries, not the largest of them. Left unbounded + /// this is the dominant term — entries are capped individually while their accumulation is + /// not, and a batch's entry count is limited only by the request body size. A batch that + /// exceeds this is answered with a single oversized-response error. + #[clap( + long, + env = "DEBUG_TRACE_SERVER_MAX_BATCH_RESPONSE_SIZE", + default_value = "1GB", + value_parser = parse_size, + )] + max_batch_response_size: u64, + + /// Address of the loopback-only admin RPC listener (e.g. `127.0.0.1:8546`). + /// + /// Serves `admin_getConcurrencyLimit` / `admin_setConcurrencyLimit`, which retune the + /// admission gate without a restart. Omitted, no admin listener runs and the limits are + /// fixed for the process's lifetime. This port has no authentication and its setters can + /// throttle request serving, so a non-loopback bind is refused at startup; reach it + /// through a port-forward or a sidecar. + #[clap(long, env = "DEBUG_TRACE_SERVER_ADMIN_ADDR")] + admin_addr: Option, + /// Estimated number of items in response cache (for initial capacity). Must be at /// least 1 — disable the cache with `--response-cache-disabled`, not with 0. #[clap( @@ -448,6 +548,25 @@ const DEFAULT_PRUNER_INTERVAL_SECS: u64 = 300; /// Default floor of recent block bodies that size-based pruning never removes. const DEFAULT_SIZE_PRUNE_MIN_RETAIN: u64 = 256; +/// Default execution-permit budget. +/// +/// Just above the highest per-handler occupancy this server has been measured sustaining +/// with zero failures, computed by Little's law from that run's request-duration counters +/// rather than from its offered concurrency — the two differ by 3x, and the offered figure +/// would over-provision by the same factor. Deliberately above every clean measurement +/// rather than at a knee: no saturation point has been established for this workload, and a +/// default that throttles a known-good one is a worse failure than a loose bound. +const DEFAULT_ADMISSION_MAX_CONCURRENT: u64 = 640; + +/// Default queue depth — roughly four seconds of backlog at the throughput measured on the +/// cold path, which keeps a full queue comfortably inside the block-fetch deadline. +const DEFAULT_ADMISSION_MAX_QUEUE: u64 = 8192; + +/// Default budget for memory-hungry tracers. Derived from memory rather than throughput: a +/// single `prestateTracer` response over a large block has been measured near a gigabyte, so +/// this figure times `--max-response-size` is what to check against the host's memory limit. +const DEFAULT_ADMISSION_HEAVY_MAX_CONCURRENT: u64 = 8; + /// Parses a human-readable size string into bytes. /// /// Accepts suffixes: `KB` (1024), `MB` (1024²), `GB` (1024³). Case-insensitive. @@ -575,9 +694,64 @@ fn validate_args(args: &Args) -> Result { (frontier vs historical) to the local DB tip" ); } + // A batch's entries admit independently, so a gate narrower than one batch's concurrent + // entries would shed part of every batch on a completely idle server. + let admission_capacity = args.admission_max_concurrent.saturating_add(args.admission_max_queue); + if !args.admission_disabled && admission_capacity < u64::from(args.batch_item_concurrency) { + eyre::bail!( + "--admission-max-concurrent ({}) + --admission-max-queue ({}) must be at least \ + --batch-item-concurrency ({}): one batch's entries admit independently, so a \ + smaller gate sheds part of every batch even on an idle server", + args.admission_max_concurrent, + args.admission_max_queue, + args.batch_item_concurrency + ); + } + // The batch builder holds whole entry bodies, so a batch cap below one entry's cap could + // never assemble even a single maximal response. + if args.max_batch_response_size < args.max_response_size { + eyre::bail!( + "--max-batch-response-size ({}) must be at least --max-response-size ({}): a batch \ + holds whole entry bodies, so a smaller batch cap could not assemble even one \ + maximal entry", + args.max_batch_response_size, + args.max_response_size + ); + } + admin_bind_addr(args)?; Ok(target) } +/// Parses `--admin-addr`, returning `None` when no admin listener was requested. +/// +/// Pure, so `validate_args` can fail fast on a bad value at startup and `main` can ask again +/// for the parsed address without threading it through — the same shape +/// `old_block_witness_timeout_secs` already uses. +fn admin_bind_addr(args: &Args) -> Result> { + let Some(raw) = args.admin_addr.as_deref() else { return Ok(None) }; + let raw = raw.trim(); + // What a templated env file renders for a variable a role does not set. + if raw.is_empty() { + eyre::bail!( + "--admin-addr was set to an empty value; omit it entirely to run without an \ + admin listener" + ); + } + // Deliberately an address literal, not a hostname: a name could resolve to a routable + // address later, defeating the loopback check below. + let addr: SocketAddr = raw.parse().map_err(|e| { + eyre::eyre!("--admin-addr ({raw}) must be an address and port, e.g. 127.0.0.1:8546: {e}") + })?; + if !addr.ip().is_loopback() { + eyre::bail!( + "--admin-addr ({addr}) must bind loopback: this port has no authentication and \ + its setters can throttle request serving. Bind 127.0.0.1 or [::1] and reach it \ + through a port-forward or a sidecar" + ); + } + Ok(Some(addr)) +} + #[tokio::main] async fn main() -> Result<()> { let args = Args::parse(); @@ -613,6 +787,13 @@ async fn main() -> Result<()> { response_cache_estimated_items = args.response_cache_estimated_items, response_compression_disabled = args.response_compression_disabled, batch_item_concurrency = args.batch_item_concurrency, + admission_disabled = args.admission_disabled, + admission_max_concurrent = args.admission_max_concurrent, + admission_max_queue = args.admission_max_queue, + admission_heavy_max_concurrent = args.admission_heavy_max_concurrent, + max_response_size = args.max_response_size, + max_batch_response_size = args.max_batch_response_size, + admin_addr = ?args.admin_addr, "Server configuration" ); @@ -865,8 +1046,50 @@ async fn main() -> Result<()> { }); } + // Inbound admission gate. `None` disables it entirely: no layer is installed and every + // request executes on arrival, as it did before this existed. + let admission = (!args.admission_disabled).then(|| { + AdmissionLimiter::new( + args.admission_max_concurrent, + args.admission_max_queue, + args.admission_heavy_max_concurrent, + ) + }); + match &admission { + // Pairing a concurrency cap with a response-size cap is what makes the worst case a + // number at all, and it is worth an operator seeing it at startup rather than + // discovering it under load. Both products are logged, because they answer different + // questions: the heavy one bounds the shapes that can actually reach the response cap, + // while the overall one is the theoretical ceiling if every admitted request returned + // a maximal body. Neither covers a tracer's intermediate allocations, which are not + // bounded by anything here. + Some(limiter) => info!( + max_concurrent = limiter.max_concurrent(), + max_queue = limiter.max_queue(), + heavy_max_concurrent = limiter.heavy_max_concurrent(), + max_permit_wait_ms = data_provider.max_permit_wait().as_millis() as u64, + max_response_size = args.max_response_size, + max_batch_response_size = args.max_batch_response_size, + worst_case_heavy_response_bytes = + limiter.heavy_max_concurrent().saturating_mul(args.max_response_size), + worst_case_response_bytes = + limiter.max_concurrent().saturating_mul(args.max_response_size), + "Admission control enabled" + ), + None => warn!( + "--admission-disabled: this process accepts unbounded concurrent work and has no \ + upper bound on the memory a burst of large traces can pin" + ), + } + // Create RPC context and module - let ctx = RpcContext::new(data_provider, chain_spec, response_cache); + let ctx = RpcContext::new( + data_provider, + chain_spec, + response_cache, + admission.clone(), + args.max_response_size as usize, + ); // Spawn watch dog checker to monitor long-running requests let watch_dog = ctx.watch_dog().clone(); @@ -880,14 +1103,31 @@ async fn main() -> Result<()> { }); let module = ctx.into_rpc_module()?; + assert_admission_covers_module(&module); - // Start server - let max_response_body_size = u32::MAX; + // Start server. One value feeds the framework's cap and the batch layer's assembly cap — + // `rpc_middleware` requires those two to stay in step — while the per-response check at + // our own serialization point is the separate, tighter bound that stops a single body + // from ever being built up twice more. + let max_response_body_size = u32::try_from(args.max_batch_response_size).unwrap_or_else(|_| { + warn!( + requested = args.max_batch_response_size, + applied = u32::MAX, + "--max-batch-response-size exceeds the JSON-RPC framework's cap; clamping" + ); + u32::MAX + }); let config = ServerConfig::builder().max_response_body_size(max_response_body_size).build(); - let rpc_middleware = RpcServiceBuilder::new().layer(rpc_middleware::ConcurrentBatchLayer::new( - args.batch_item_concurrency as usize, - max_response_body_size as usize, - )); + // Order is load-bearing: the batch layer is outermost, so the admission layer below it + // sees single calls *and* every batch entry. Reversed, an N-entry batch would pass the + // gate as one unit — which is the traffic shape that has actually taken this server down. + // `batch_entries_are_individually_gated` fails if these are swapped. + let rpc_middleware = RpcServiceBuilder::new() + .layer(rpc_middleware::ConcurrentBatchLayer::new( + args.batch_item_concurrency as usize, + max_response_body_size as usize, + )) + .option_layer(admission.clone().map(admission::AdmissionLayer::new)); let server = Server::builder() .set_config(config) .set_rpc_middleware(rpc_middleware) @@ -897,12 +1137,56 @@ async fn main() -> Result<()> { let addr = server.local_addr()?; let handle = server.start(module); + // The bound admin address, kept only for the record; the listener itself is owned by its + // own thread for the process's lifetime (see `admin::spawn`). + let _admin_addr = match (admin_bind_addr(&args)?, admission) { + (Some(admin_addr), Some(limiter)) => { + Some(admin::spawn(admin_addr, limiter, u64::from(args.batch_item_concurrency))?) + } + (Some(_), None) => { + warn!("--admin-addr is set but --admission-disabled: no limits to serve, skipping"); + None + } + (None, _) => { + warn!( + "--admin-addr not set: admission limits are fixed for this process's lifetime \ + and can only be changed by restarting" + ); + None + } + }; + info!(listen_addr = %addr, "Server started"); handle.stopped().await; Ok(()) } +/// Fails fast if a registered method escapes the admission gate's allowlist. +/// +/// The allowlist is spelled by name, so a method added later would silently never be gated — +/// the failure mode of an omission here is an unprotected endpoint, discovered under load. +/// `debug_getCacheStatus` is the one deliberate exemption; see `metrics::GATED_METHODS`. +fn assert_admission_covers_module(module: &jsonrpsee::server::RpcModule<()>) { + if let Some(name) = ungated_method(module.method_names()) { + panic!( + "method {name} is registered but neither gated by admission control nor \ + deliberately exempt; add it to metrics::GATED_METHODS or to the exemption list" + ); + } +} + +/// The first registered method that is neither gated nor deliberately exempt, if any. +fn ungated_method<'a>(names: impl Iterator) -> Option<&'a str> { + // The one endpoint that does no I/O and reports what the server is doing; see + // `metrics::GATED_METHODS` for why it is exempt. + const EXEMPT: &[&str] = + &[metrics::METHOD_DEBUG_GET_CACHE_STATUS, metrics::TIMED_METHOD_DEBUG_GET_CACHE_STATUS]; + names + .filter(|name| !EXEMPT.contains(name)) + .find(|name| !metrics::is_gated(metrics::method_label(name))) +} + /// Initializes the validator database if data_dir is provided. /// Returns the database if configured, None otherwise. /// Note: Chain tracker is spawned separately in main() to allow passing the response cache @@ -1401,6 +1685,141 @@ mod tests { assert!(disabled_via_env); } + /// The admission allowlist is spelled by name, so a method added later would silently + /// never be gated — an unprotected endpoint, discovered under load. + #[test] + fn every_registered_method_is_gated_or_deliberately_exempt() { + let registered: Vec<&str> = metrics::ALL_METHOD_NAMES + .iter() + .copied() + .chain(metrics::TIMED_METHOD_ALIASES.iter().map(|(alias, _)| *alias)) + .collect(); + assert_eq!(ungated_method(registered.iter().copied()), None); + + assert_eq!( + ungated_method(["debug_traceBlockByNumber", "debug_newThing"].into_iter()), + Some("debug_newThing"), + "an unrecognized method must be reported, not folded into `unknown` and ignored" + ); + } + + #[test] + fn admission_flag_defaults_and_env() { + let guard = stateless_test_utils::env::env_lock(); + + let args = parse_args(&[]); + assert_eq!(args.admission_max_concurrent, DEFAULT_ADMISSION_MAX_CONCURRENT); + assert_eq!(args.admission_max_queue, DEFAULT_ADMISSION_MAX_QUEUE); + assert_eq!(args.admission_heavy_max_concurrent, DEFAULT_ADMISSION_HEAVY_MAX_CONCURRENT); + assert!(!args.admission_disabled); + assert_eq!(args.max_response_size, 256 * 1024 * 1024); + assert_eq!(args.max_batch_response_size, 1024 * 1024 * 1024); + assert!(args.admin_addr.is_none()); + + // Zero execution permits would park every request forever; zero queue is a legitimate + // "execute or shed" configuration and must stay accepted. + let base = + ["debug-trace-server", "--rpc-endpoint", "http://r", "--witness-endpoint", "http://w"]; + for flag in ["--admission-max-concurrent", "--admission-heavy-max-concurrent"] { + assert!( + Args::try_parse_from(base.iter().chain(&[flag, "0"])).is_err(), + "{flag} 0 must be rejected at parse time" + ); + } + assert_eq!(parse_args(&["--admission-max-queue", "0"]).admission_max_queue, 0); + + // Env attributes are what container deployments actually use, and a typo in one ships + // silently — a default-looking value with nothing pointing at the cause. + for (var, flag_value) in [ + ("DEBUG_TRACE_SERVER_ADMISSION_MAX_CONCURRENT", "77"), + ("DEBUG_TRACE_SERVER_ADMISSION_MAX_QUEUE", "78"), + ("DEBUG_TRACE_SERVER_ADMISSION_HEAVY_MAX_CONCURRENT", "79"), + ] { + let read = stateless_test_utils::env::with_env_var(&guard, var, flag_value, || { + let args = parse_args(&[]); + match var { + "DEBUG_TRACE_SERVER_ADMISSION_MAX_CONCURRENT" => args.admission_max_concurrent, + "DEBUG_TRACE_SERVER_ADMISSION_MAX_QUEUE" => args.admission_max_queue, + _ => args.admission_heavy_max_concurrent, + } + }); + assert_eq!(read.to_string(), flag_value, "{var} did not reach its field"); + } + + let sizes = stateless_test_utils::env::with_env_var( + &guard, + "DEBUG_TRACE_SERVER_MAX_RESPONSE_SIZE", + "64MB", + || parse_args(&[]).max_response_size, + ); + assert_eq!(sizes, 64 * 1024 * 1024); + } + + /// The admin port has no authentication and its setters can throttle request serving, so a + /// non-loopback bind is refused by name rather than warned about. + #[test] + fn admin_addr_must_be_a_loopback_literal() { + for accepted in ["127.0.0.1:8546", "127.0.0.5:1", "[::1]:8546"] { + let args = parse_args(&["--admin-addr", accepted]); + assert!(admin_bind_addr(&args).is_ok(), "{accepted} should be accepted"); + } + + // A hostname is refused even when it resolves to loopback today: it could resolve + // elsewhere later, which would defeat the check silently. + for rejected in ["0.0.0.0:8546", "10.1.2.3:8546", "[::]:8546", "localhost:8546", "8546"] { + let args = parse_args(&["--admin-addr", rejected]); + let err = admin_bind_addr(&args).unwrap_err().to_string(); + assert!(err.contains("--admin-addr"), "the error must name the flag: {err}"); + } + + // What a templated env file renders for a variable a role does not set. + let args = parse_args(&["--admin-addr", " "]); + assert!(admin_bind_addr(&args).unwrap_err().to_string().contains("--admin-addr")); + + assert!(admin_bind_addr(&parse_args(&[])).unwrap().is_none(), "absent means disabled"); + } + + /// A gate with less total capacity than one batch's concurrent entries sheds part of every + /// batch on a completely idle server — caught at startup, by name. + #[test] + fn admission_capacity_must_cover_one_batch() { + let args = parse_args(&[ + "--batch-item-concurrency", + "16", + "--admission-max-concurrent", + "4", + "--admission-max-queue", + "4", + ]); + let err = validate_args(&args).expect_err("8 of capacity cannot serve a 16-wide batch"); + let err = err.to_string(); + assert!(err.contains("--admission-max-concurrent"), "{err}"); + assert!(err.contains("--batch-item-concurrency"), "{err}"); + + // The kill switch takes the rule out of play along with the gate. + let args = parse_args(&[ + "--batch-item-concurrency", + "16", + "--admission-max-concurrent", + "4", + "--admission-max-queue", + "4", + "--admission-disabled", + ]); + assert!(validate_args(&args).is_ok()); + } + + /// A batch holds whole entry bodies, so a batch cap under one entry's cap could never + /// assemble even a single maximal response. + #[test] + fn batch_response_cap_must_cover_one_response() { + let args = + parse_args(&["--max-response-size", "512MB", "--max-batch-response-size", "256MB"]); + let err = validate_args(&args).expect_err("a batch cap below the entry cap").to_string(); + assert!(err.contains("--max-batch-response-size"), "{err}"); + assert!(validate_args(&parse_args(&["--max-response-size", "512MB"])).is_ok()); + } + /// Batch concurrency knob: default, CLI/env override, and the zero rejection. #[test] fn batch_item_concurrency_flag() { diff --git a/bin/debug-trace-server/src/metrics.rs b/bin/debug-trace-server/src/metrics.rs index 565757bd..6f68c1c9 100644 --- a/bin/debug-trace-server/src/metrics.rs +++ b/bin/debug-trace-server/src/metrics.rs @@ -63,6 +63,10 @@ pub const CACHE_TYPE_TRACE: &str = "trace_block"; pub const CACHE_TYPE_BLOCK_DATA: &str = "block_data"; // All known RPC methods (for resolving &str → &'static str) +/// [`ALL_METHODS`] exposed for the admission-coverage test in `main`. +#[cfg(test)] +pub const ALL_METHOD_NAMES: &[&str] = ALL_METHODS; + const ALL_METHODS: &[&str] = &[ METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, METHOD_DEBUG_TRACE_BLOCK_BY_HASH, @@ -72,6 +76,32 @@ const ALL_METHODS: &[&str] = &[ METHOD_TRACE_TRANSACTION, ]; +/// The methods the inbound admission gate applies to: everything that fetches a block and +/// runs a tracer, i.e. everything whose cost is a block-unit. +/// +/// `debug_getCacheStatus` is deliberately absent — it is pure atomic reads, touches neither +/// upstream nor EVM, and shedding the one endpoint an operator uses to ask what the server +/// is doing, precisely while it is shedding, would be self-defeating. Unknown methods are +/// absent too: the framework answers them `-32601` in microseconds, so gating buys nothing +/// and would replace that with a misleading `-32013`. +/// +/// This is the single source of truth for the allowlist: the admission layer gates exactly +/// these, and [`pre_register_all_metrics`] registers the `shed` arrival series for exactly +/// these. Callers must resolve the wire name through [`method_label`] first, so `timed_` +/// aliases are covered. +pub const GATED_METHODS: &[&str] = &[ + METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, + METHOD_DEBUG_TRACE_BLOCK_BY_HASH, + METHOD_DEBUG_TRACE_TRANSACTION, + METHOD_TRACE_BLOCK, + METHOD_TRACE_TRANSACTION, +]; + +/// Whether the admission gate applies to an already-resolved method label. +pub fn is_gated(method: &'static str) -> bool { + GATED_METHODS.contains(&method) +} + /// Maps an arbitrary method string onto one of the known `&'static str` labels, so a /// caller that only has a borrowed name can still label a metric without allocating. /// Unknown methods collapse to `"unknown"`, keeping label cardinality bounded against @@ -139,6 +169,11 @@ pub enum ErrorReason { /// top-level params, unparsable batch entry) — recorded by the RPC middleware's /// fallback, never by a handler. Rejected, + /// Shed by the inbound admission gate: the request arrived while queue + execution + /// capacity was already full, or waited for an execution permit until so little of its + /// budget remained that the witness stage could no longer fit. Answered `-32013` + /// without the tracer ever running. + Overloaded, /// An error response with a non-framework code left the server without a /// handler-recorded reason — a handler ran but bypassed the error funnel. This series /// sitting at nonzero is a code-drift alarm, not an operating state: it keeps a future @@ -157,6 +192,7 @@ impl ErrorReason { Self::TraceFailed => "trace_failed", Self::Internal => "internal", Self::Rejected => "rejected", + Self::Overloaded => "overloaded", Self::Unattributed => "unattributed", } } @@ -170,6 +206,7 @@ impl ErrorReason { Self::TraceFailed, Self::Internal, Self::Rejected, + Self::Overloaded, Self::Unattributed, ]; } @@ -462,9 +499,11 @@ fn record_upstream_deadline_exceeded(method: &'static str) { /// shapes bypass the response cache. const REQUEST_SHAPE_TOTAL: &str = "debug_trace_request_shape_total"; -/// Every label emitted by `RequestShape::label`, for pre-registration and tests — plus -/// `rejected`, recorded by the RPC middleware for requests the framework answered before -/// the handler ran (see [`record_framework_rejection`]). +/// Every label emitted by `RequestShape::label`, for pre-registration and tests — plus the +/// two the request never reached a tracer for: `rejected`, recorded by the RPC middleware +/// for requests the framework answered before the handler ran (see +/// [`record_framework_rejection`]), and `shed`, recorded by the admission layer for +/// requests turned away before the handler ran (see [`record_admission_shed`]). pub const REQUEST_SHAPES: &[&str] = &[ "default", "call_tracer", @@ -476,6 +515,7 @@ pub const REQUEST_SHAPES: &[&str] = &[ "js_tracer", "mux_tracer", "rejected", + "shed", ]; /// Records one request of the given parameter shape for `method`. @@ -701,6 +741,89 @@ impl ChainSyncMetrics { } } +/// Inbound admission-gate occupancy, labeled `(method)`. +/// +/// Two independent gauges rather than a queued/executing pair, because the two phases are +/// raised in different places: `in_flight` by the RPC middleware for the whole request, +/// `executing` by the handler for the span it holds an execution permit. Queue depth is +/// `in_flight - executing`, derived at query time. +/// +/// Both are lowered by RAII guards: a request cancelled while queued, or midway through +/// execution, must not leave a gauge stuck high forever. +#[derive(Clone, Metrics)] +#[metrics(scope = "debug_trace")] +pub struct AdmissionMetrics { + /// Requests admitted by the gate and not yet finished. + admission_in_flight: Gauge, + /// Requests holding an execution permit. + admission_executing: Gauge, +} + +impl AdmissionMetrics { + /// Creates admission metrics for a specific RPC method. + pub fn new_for_method(method: &'static str) -> Self { + Self::new_with_labels(&[("method", method)]) + } + + /// Adjusts the admitted-and-unfinished gauge. + pub fn in_flight_delta(&self, delta: f64) { + self.admission_in_flight.increment(delta); + } + + /// Adjusts the holding-an-execution-permit gauge. + pub fn executing_delta(&self, delta: f64) { + self.admission_executing.increment(delta); + } +} + +/// Requests holding a permit from the heavy-shape sub-cap. Unlabeled: the sub-cap is a +/// single process-wide budget, and which method asked for it is already on +/// `admission_executing`. +const ADMISSION_HEAVY_EXECUTING: &str = "debug_trace_admission_heavy_executing"; + +/// Time a request spent waiting for an execution permit. Unlabeled, following the +/// `debug_trace_r2_witness_queue_wait_seconds` precedent: under a single global limiter the +/// wait is method-independent, and the method dimension is already on the gauges. +/// +/// Biased by construction: only waits that ended in a permit are sampled. A wait that ended +/// in a client hangup lands on `requests_cancelled_total`, and one clamped by the deadline +/// lands on `rpc_errors_total{reason="overloaded"}`. +const ADMISSION_PERMIT_WAIT_SECONDS: &str = "debug_trace_admission_permit_wait_seconds"; + +/// The limits currently in effect. Published at startup and on every admin write — these are +/// runtime-mutable, so without them a dashboard cannot tell what the gate is actually +/// enforcing, and a shed spike is unattributable to the change that caused it. +const ADMISSION_MAX_CONCURRENT: &str = "debug_trace_admission_max_concurrent"; +/// See [`ADMISSION_MAX_CONCURRENT`]. +const ADMISSION_MAX_QUEUE: &str = "debug_trace_admission_max_queue"; +/// See [`ADMISSION_MAX_CONCURRENT`]. +const ADMISSION_HEAVY_MAX_CONCURRENT: &str = "debug_trace_admission_heavy_max_concurrent"; + +/// Responses discarded for exceeding `--max-response-size`, labeled `(method)`. +const RESPONSE_OVERSIZED_TOTAL: &str = "debug_trace_response_oversized_total"; + +/// Records the wait one request spent queued for an execution permit. +pub fn record_admission_permit_wait(seconds: f64) { + histogram!(ADMISSION_PERMIT_WAIT_SECONDS).record(seconds); +} + +/// Publishes the limits currently in effect. +pub fn record_admission_limits(max_concurrent: u64, max_queue: u64, heavy_max_concurrent: u64) { + gauge!(ADMISSION_MAX_CONCURRENT).set(max_concurrent as f64); + gauge!(ADMISSION_MAX_QUEUE).set(max_queue as f64); + gauge!(ADMISSION_HEAVY_MAX_CONCURRENT).set(heavy_max_concurrent as f64); +} + +/// Adjusts the heavy sub-cap occupancy gauge. +pub fn record_admission_heavy_delta(delta: f64) { + gauge!(ADMISSION_HEAVY_EXECUTING).increment(delta); +} + +/// Records one response discarded for exceeding the configured size cap. +pub fn record_response_oversized(method: &'static str) { + counter!(RESPONSE_OVERSIZED_TOTAL, "method" => method).increment(1); +} + /// Pre-registers all metrics so they appear in Prometheus from startup (with zero values). fn pre_register_all_metrics() { // Request Layer: RPC method metrics — every method that can record a served request, @@ -807,16 +930,37 @@ fn pre_register_all_metrics() { counter!(REQUEST_SHAPE_TOTAL, "method" => method, "shape" => *shape).increment(0); } } - // Arrival series for the opts-less methods: "default" at handler entry, "rejected" - // via the middleware fallback. - for method in [METHOD_TRACE_BLOCK, METHOD_TRACE_TRANSACTION, METHOD_DEBUG_GET_CACHE_STATUS] { - for shape in ["default", "rejected"] { + // Arrival series for the opts-less methods: "default" at handler entry, "rejected" via + // the middleware fallback, plus "shed" for the two the admission gate applies to. The + // three opts-taking methods get "shed" from `REQUEST_SHAPES` above; `debug_getCacheStatus` + // is exempt from the gate (see `GATED_METHODS`) so it has no `shed` series at all. + for method in [METHOD_TRACE_BLOCK, METHOD_TRACE_TRANSACTION] { + for shape in ["default", "rejected", "shed"] { counter!(REQUEST_SHAPE_TOTAL, "method" => method, "shape" => shape).increment(0); } } + for shape in ["default", "rejected"] { + counter!(REQUEST_SHAPE_TOTAL, "method" => METHOD_DEBUG_GET_CACHE_STATUS, "shape" => shape) + .increment(0); + } // The `unknown` fold target only ever arrives through the middleware's rejected pair. counter!(REQUEST_SHAPE_TOTAL, "method" => "unknown", "shape" => "rejected").increment(0); + // Request Layer: admission gate. Occupancy is per gated method; the limit gauges are + // global and are re-published on every admin write. + for method in GATED_METHODS.iter().copied() { + let _ = AdmissionMetrics::new_for_method(method); + } + let _ = histogram!(ADMISSION_PERMIT_WAIT_SECONDS); + gauge!(ADMISSION_HEAVY_EXECUTING).set(0.0); + + // Request Layer: responses discarded for exceeding `--max-response-size`. Every method + // that can produce a trace body participates; a nonzero value here is the signal that + // clients are asking for more than the process is willing to materialize. + for method in GATED_METHODS.iter().copied() { + counter!(RESPONSE_OVERSIZED_TOTAL, "method" => method).increment(0); + } + // Data Fetch Layer: canonical number → hash resolution for (source, outcome) in [ ("db", "ok"), @@ -864,6 +1008,13 @@ const BLOCK_DISTANCE_BUCKETS: &[f64] = &[0.0, 1.0, 5.0, 10.0, 50.0, 100.0, 500.0 /// combined across replicas or alerted on cleanly. const BODY_CPU_TIME_BUCKETS: &[f64] = &[0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5]; +/// Wait for an inbound execution permit, seconds. Spans "uncontended" (microseconds) to the +/// deadline clamp (seconds). Explicit buckets for the same reason as +/// [`BODY_CPU_TIME_BUCKETS`]: without them the exporter renders per-instance summary +/// quantiles that cannot be aggregated across replicas. +const ADMISSION_WAIT_BUCKETS: &[f64] = + &[0.0005, 0.001, 0.005, 0.01, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0]; + /// (metric_name, buckets) pairs applied via `set_buckets_for_metric` at startup. const BUCKET_SPECS: &[(&str, &[f64])] = &[ ("debug_trace_evm_block_tx_count", TX_COUNT_BUCKETS), @@ -872,6 +1023,7 @@ const BUCKET_SPECS: &[(&str, &[f64])] = &[ ("debug_trace_reorg_depth", REORG_DEPTH_BUCKETS), ("debug_trace_witness_bytes", BYTE_BUCKETS), ("debug_trace_body_cpu_time_seconds", BODY_CPU_TIME_BUCKETS), + ("debug_trace_admission_permit_wait_seconds", ADMISSION_WAIT_BUCKETS), ]; /// Initializes the Prometheus metrics exporter. @@ -955,6 +1107,21 @@ pub fn record_framework_rejection(method: &'static str) { record_rpc_error(method, ErrorReason::Rejected); } +/// Records a request the admission gate turned away before its handler ran, as the balanced +/// pair `request_shape_total{shape="shed"}` + `rpc_errors_total{reason="overloaded"}` — an +/// arrival and an outcome, so the accounting identity holds for requests no handler saw. +/// Takes the already-resolved label, like [`record_framework_rejection`]. +/// +/// Must be called from inside the request future, never from a layer's synchronous prefix: +/// [`record_rpc_error`] sets the `ERROR_SELF_REPORTED` task-local that tells the middleware +/// fallback this `-32013` is already accounted for, and that task-local only exists inside +/// [`track_handler_errors`]' scope. Recorded outside it, every shed would both double-count +/// the error side and false-fire the `unattributed` drift alarm. +pub fn record_admission_shed(method: &'static str) { + record_request_shape(method, "shed"); + record_rpc_error(method, ErrorReason::Overloaded); +} + /// Records a request whose handler future was dropped before producing a response — /// in practice a client that hung up or timed out on its own side. /// diff --git a/bin/debug-trace-server/src/response_cache.rs b/bin/debug-trace-server/src/response_cache.rs index 89e0fa2a..764d9ade 100644 --- a/bin/debug-trace-server/src/response_cache.rs +++ b/bin/debug-trace-server/src/response_cache.rs @@ -37,6 +37,7 @@ use quick_cache::{Lifecycle, Weighter, sync::Cache}; use tracing::debug; use crate::{ + admission::TraceWeight, metrics::{CACHE_TYPE_DEBUG_TRACE, CACHE_TYPE_TRACE, CacheMetrics, CacheStats}, raw_json::RawJson, }; @@ -256,6 +257,33 @@ impl RequestShape { } /// Metrics shape label for this request. + /// How much memory this request's tracer is expected to want, for the admission gate's + /// heavy sub-cap. + /// + /// Matched structurally rather than on [`Self::label`] so that adding a tracer forces a + /// decision here instead of silently defaulting to cheap. Every bypassed shape counts as + /// heavy by construction: a shape bypasses the cache precisely because its output is not + /// determined by a bounded key, which is the same reason its size is not bounded either. + pub fn weight(&self) -> TraceWeight { + match self { + Self::Cacheable(variant) => match variant { + // `Default` is the struct logger, which emits a record per executed opcode — + // the largest output of any shape here, and the only thing separating it from + // its `Bypass("struct_logger_config")` sibling below is a flag that changes + // its size, not its kind. Classifying the two differently would let the + // heaviest traffic in through the cheap door. + ResponseVariant::Default | ResponseVariant::PrestateTracer(_) => TraceWeight::Heavy, + ResponseVariant::CallTracer(_) | + ResponseVariant::FlatCallTracer(_) | + ResponseVariant::FourByteTracer | + ResponseVariant::NoopTracer => TraceWeight::Normal, + }, + Self::Bypass(_) => TraceWeight::Heavy, + // Rejected before it can execute, so it never reaches a permit. + Self::InvalidTracerConfig { .. } => TraceWeight::Normal, + } + } + pub fn label(&self) -> &'static str { match self { Self::Cacheable(variant) => variant.label(), diff --git a/bin/debug-trace-server/src/rpc_middleware.rs b/bin/debug-trace-server/src/rpc_middleware.rs index a7a8fa77..d4a35c2c 100644 --- a/bin/debug-trace-server/src/rpc_middleware.rs +++ b/bin/debug-trace-server/src/rpc_middleware.rs @@ -197,10 +197,11 @@ fn settle_response(rp: &MethodResponse, handler_reported: bool, guard: CancelGua // The framework swapped a handler's *Ok* for the oversized-response error // after the handler already recorded arrival + served: the books are balanced, // and recording again here would both over-count the identity and false-fire - // the drift alarm. Unreachable while the server pins the response cap to - // u32::MAX — load-bearing the day a real `--max-response-size` lands. The - // client-saw-error / books-say-served mismatch is accepted like the other - // documented approximations. + // the drift alarm. Reachable since `--max-batch-response-size` became a real + // bound: an entry body that passes the per-response check can still push the + // assembled batch past the framework's cap. The client-saw-error / + // books-say-served mismatch is accepted like the other documented + // approximations. Some(OVERSIZED_RESPONSE_CODE) => {} Some(_) => { crate::metrics::record_rpc_error(method, crate::metrics::ErrorReason::Unattributed) @@ -414,9 +415,22 @@ mod tests { module: RpcModule<()>, concurrency: usize, max_response_body_size: usize, + ) -> (SocketAddr, ServerHandle) { + spawn_with_limits(module, concurrency, max_response_body_size, None).await + } + + /// [`spawn_with`] plus an optional admission gate, installed *below* the batch layer + /// exactly as production does — so these tests exercise the real layer order rather than + /// a replica of it. + async fn spawn_with_limits( + module: RpcModule<()>, + concurrency: usize, + max_response_body_size: usize, + limiter: Option>, ) -> (SocketAddr, ServerHandle) { let rpc_middleware = RpcServiceBuilder::new() - .layer(ConcurrentBatchLayer::new(concurrency, max_response_body_size)); + .layer(ConcurrentBatchLayer::new(concurrency, max_response_body_size)) + .option_layer(limiter.map(crate::admission::AdmissionLayer::new)); let http_middleware = tower::ServiceBuilder::new().layer(crate::timing::TimingHeaderLayer); let server = Server::builder() .set_rpc_middleware(rpc_middleware) @@ -636,6 +650,46 @@ mod tests { assert!(rp["error"]["code"].is_i64()); } + // Accounting-series names, shared by every test that reads the identity. + const SHAPE: &str = "debug_trace_request_shape_total"; + // The derive-based served counter keeps its raw dotted scope name here — the + // dot-to-underscore rename happens in the Prometheus exporter, not the recorder. + const SERVED: &str = "debug_trace.rpc_requests_total"; + const ERRORS: &str = "debug_trace_rpc_errors_total"; + const CANCELLED: &str = "debug_trace_requests_cancelled_total"; + + type Acc = std::collections::HashMap<(String, Vec<(String, String)>), u64>; + + /// Folds one drain of `snapshotter` into `acc`. + /// + /// `Snapshotter::snapshot` *drains* the recorder (each counter swaps to zero), so every + /// observation has to funnel through one accumulator that survives repeated polls. + fn drain(snapshotter: &metrics_util::debugging::Snapshotter, acc: &mut Acc) { + use metrics_util::debugging::DebugValue; + for (ck, _, _, value) in snapshotter.snapshot().into_vec() { + if let DebugValue::Counter(v) = value { + let key = ck.key(); + let labels: Vec<(String, String)> = + key.labels().map(|l| (l.key().to_string(), l.value().to_string())).collect(); + *acc.entry((key.name().to_string(), labels)).or_default() += v; + } + } + } + + /// Sums every accumulated counter matching `metric` and all of `labels` (a subset match, + /// so a method-only query sums across shapes and reasons). + fn read(acc: &Acc, metric: &str, labels: &[(&str, &str)]) -> u64 { + acc.iter() + .filter(|((name, ls), _)| { + name.as_str() == metric && + labels.iter().all(|(lk, lv)| { + ls.iter().any(|(k, v)| k.as_str() == *lk && v.as_str() == *lv) + }) + }) + .map(|(_, v)| *v) + .sum() + } + /// Handlers following the real handlers' accounting contract — arrival recorded at /// entry, then exactly one outcome — plus one that deliberately bypasses the error /// funnel, mimicking the drift `reason="unattributed"` exists to catch. Registered @@ -682,6 +736,181 @@ mod tests { module } + /// A gated method slow enough to hold its capacity while siblings arrive, and the one + /// exempt method. Both follow the real handlers' accounting contract: arrival recorded at + /// entry, then exactly one outcome. + fn admission_module() -> RpcModule<()> { + use crate::metrics; + let mut module = RpcModule::new(()); + module + .register_async_method(metrics::METHOD_TRACE_BLOCK, |_, _, _| async { + metrics::record_request_shape(metrics::METHOD_TRACE_BLOCK, "default"); + tokio::time::sleep(Duration::from_millis(SLOW_MS)).await; + metrics::record_rpc_request(metrics::METHOD_TRACE_BLOCK, 0.001); + "ok" + }) + .unwrap(); + module + .register_async_method(metrics::METHOD_DEBUG_GET_CACHE_STATUS, |_, _, _| async { + metrics::record_request_shape(metrics::METHOD_DEBUG_GET_CACHE_STATUS, "default"); + metrics::record_rpc_request(metrics::METHOD_DEBUG_GET_CACHE_STATUS, 0.001); + "status" + }) + .unwrap(); + module + .register_alias( + metrics::TIMED_METHOD_DEBUG_GET_CACHE_STATUS, + metrics::METHOD_DEBUG_GET_CACHE_STATUS, + ) + .unwrap(); + module + } + + /// Every entry of a batch admits on its own account. + /// + /// This is the layer-order pin. `ConcurrentBatch` must sit *outside* the admission layer, + /// because it decomposes batches into per-entry `call`s rather than delegating to an inner + /// `batch`. Swap the two `.layer()` calls in `main` and an N-entry batch passes the gate as + /// a single unit — no compile error, no other test failing, and the one traffic shape that + /// has actually exhausted this server sails straight through. Here that shows up as all + /// four entries succeeding against a gate with room for one. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn batch_entries_are_individually_gated() { + let limiter = crate::admission::AdmissionLimiter::new(1, 0, 1); + let (addr, _handle) = + spawn_with_limits(admission_module(), 4, u32::MAX as usize, Some(limiter)).await; + + let batch = r#"[ + {"jsonrpc": "2.0", "id": 1, "method": "trace_block", "params": []}, + {"jsonrpc": "2.0", "id": 2, "method": "trace_block", "params": []}, + {"jsonrpc": "2.0", "id": 3, "method": "trace_block", "params": []}, + {"jsonrpc": "2.0", "id": 4, "method": "trace_block", "params": []} + ]"#; + let response = post_raw(addr, batch.to_string()).await; + let entries = response.as_array().expect("a batch answers with an array"); + assert_eq!(entries.len(), 4); + + let shed = entries + .iter() + .filter(|e| e["error"]["code"] == json!(crate::admission::QUEUE_FULL_CODE)) + .count(); + let served = entries.iter().filter(|e| e["result"].is_string()).count(); + assert!(served >= 1, "the gate's one unit of capacity must serve someone: {response}"); + assert!( + shed >= 1, + "entries admit individually, so a gate with room for one must shed the rest: \ + {response}" + ); + assert_eq!(shed + served, 4, "every entry landed on exactly one outcome: {response}"); + } + + /// The shed response carries mega-reth's `ConcurrencyLimiter` contract byte for byte, so + /// whatever already backs off for the node backs off for us. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn shed_response_matches_the_queue_full_contract() { + let limiter = crate::admission::AdmissionLimiter::new(1, 0, 1); + let (addr, _handle) = + spawn_with_limits(admission_module(), 4, u32::MAX as usize, Some(limiter)).await; + + let call = + json!({"jsonrpc": "2.0", "id": 1, "method": "trace_block", "params": []}).to_string(); + let held = tokio::spawn(post_raw(addr, call.clone())); + tokio::time::sleep(Duration::from_millis(SLOW_MS / 4)).await; + let shed = post_raw(addr, call).await; + + assert_eq!(shed["error"]["code"], json!(crate::admission::QUEUE_FULL_CODE)); + assert_eq!(shed["error"]["message"], json!(crate::admission::QUEUE_FULL_MESSAGE)); + assert_eq!(shed["id"], json!(1), "a shed response still answers the request it refused"); + held.await.unwrap(); + } + + /// The one exempt method keeps answering while the gate is shedding everything else. + /// + /// Also pins that the exemption is matched on the `timed_`-stripped name: the gateway adds + /// that prefix by default, so an exemption written against the bare wire name would never + /// match in production and the operator's only introspection endpoint would be shed + /// exactly when it is needed. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn exempt_method_answers_while_shedding() { + let limiter = crate::admission::AdmissionLimiter::new(1, 0, 1); + let (addr, _handle) = + spawn_with_limits(admission_module(), 4, u32::MAX as usize, Some(limiter)).await; + + let held = tokio::spawn(post_raw( + addr, + json!({"jsonrpc": "2.0", "id": 1, "method": "trace_block", "params": []}).to_string(), + )); + tokio::time::sleep(Duration::from_millis(SLOW_MS / 4)).await; + + for method in ["debug_getCacheStatus", "timed_debug_getCacheStatus"] { + let response = post_raw( + addr, + json!({"jsonrpc": "2.0", "id": 2, "method": method, "params": []}).to_string(), + ) + .await; + assert_eq!(response["result"], json!("status"), "{method} must stay reachable"); + } + held.await.unwrap(); + } + + /// Shedding keeps the books balanced, and does not read as drift. + /// + /// Two things are pinned. The balanced pair: a shed records one arrival + /// (`shape="shed"`) and one outcome (`reason="overloaded"`), so the identity closes for a + /// request no handler ever saw. And `reason="unattributed"` staying at zero: `-32013` is + /// not a framework code, so if the shed were recorded outside `track_handler_errors`' + /// task-local scope, `settle_response` would charge every one of them to the drift alarm + /// as well — silently doubling the error side and paging on a healthy server. + #[test] + fn admission_shed_keeps_the_identity_closed() { + use metrics_util::debugging::DebuggingRecorder; + + let recorder = DebuggingRecorder::new(); + let snapshotter = recorder.snapshotter(); + let mut acc = Acc::new(); + + let rt = tokio::runtime::Builder::new_current_thread().enable_all().build().unwrap(); + metrics::with_local_recorder(&recorder, || { + rt.block_on(async { + let limiter = crate::admission::AdmissionLimiter::new(1, 0, 1); + let (addr, _handle) = + spawn_with_limits(admission_module(), 4, u32::MAX as usize, Some(limiter)) + .await; + let call = + json!({"jsonrpc": "2.0", "id": 1, "method": "trace_block", "params": []}) + .to_string(); + // One holds the single unit of capacity; the rest arrive while it does. + let calls: Vec<_> = + (0..4).map(|_| tokio::spawn(post_raw(addr, call.clone()))).collect(); + for call in calls { + call.await.unwrap(); + } + }) + }); + drain(&snapshotter, &mut acc); + + let method = [("method", "trace_block")]; + let shed = read(&acc, SHAPE, &[("method", "trace_block"), ("shape", "shed")]); + assert!(shed >= 1, "a gate with room for one must have shed something"); + assert_eq!( + shed, + read(&acc, ERRORS, &[("method", "trace_block"), ("reason", "overloaded")]), + "every shed arrival has exactly one matching outcome" + ); + assert_eq!( + read(&acc, ERRORS, &[("reason", "unattributed")]), + 0, + "a shed must never also land on the drift alarm" + ); + assert_eq!( + read(&acc, SHAPE, &method), + read(&acc, SERVED, &method) + + read(&acc, ERRORS, &method) + + read(&acc, CANCELLED, &method), + "shape = served + errors + cancelled" + ); + } + /// End-to-end pin of the accounting identity `shape = requests + errors + cancelled` /// per method — the contract that otherwise lives only in AGENTS.md prose. One pass /// drives every terminal path through a real server: served (single call and batch @@ -695,47 +924,12 @@ mod tests { /// running tests stay invisible to it. #[test] fn accounting_identity_holds_end_to_end() { - use metrics_util::debugging::{DebugValue, DebuggingRecorder}; - - const SHAPE: &str = "debug_trace_request_shape_total"; - // The derive-based served counter keeps its raw dotted scope name here — the - // dot-to-underscore rename happens in the Prometheus exporter, not the recorder. - const SERVED: &str = "debug_trace.rpc_requests_total"; - const ERRORS: &str = "debug_trace_rpc_errors_total"; - const CANCELLED: &str = "debug_trace_requests_cancelled_total"; - - type Acc = std::collections::HashMap<(String, Vec<(String, String)>), u64>; + use metrics_util::debugging::DebuggingRecorder; let recorder = DebuggingRecorder::new(); let snapshotter = recorder.snapshotter(); - // `Snapshotter::snapshot` *drains* the recorder (each counter swaps to zero), so - // every observation funnels through one accumulator that survives repeated polls. - let drain_into = |acc: &mut Acc| { - for (ck, _, _, value) in snapshotter.snapshot().into_vec() { - if let DebugValue::Counter(v) = value { - let key = ck.key(); - let labels: Vec<(String, String)> = key - .labels() - .map(|l| (l.key().to_string(), l.value().to_string())) - .collect(); - *acc.entry((key.name().to_string(), labels)).or_default() += v; - } - } - }; - // Sums every accumulated counter matching `metric` and all of `labels` (a subset - // match, so a method-only query sums across shapes/reasons). - let read = |acc: &Acc, metric: &str, labels: &[(&str, &str)]| -> u64 { - acc.iter() - .filter(|((name, ls), _)| { - name.as_str() == metric && - labels.iter().all(|(lk, lv)| { - ls.iter().any(|(k, v)| k.as_str() == *lk && v.as_str() == *lv) - }) - }) - .map(|(_, v)| *v) - .sum() - }; let mut acc = Acc::new(); + let drain_into = |acc: &mut Acc| drain(&snapshotter, acc); let rt = tokio::runtime::Builder::new_current_thread().enable_all().build().unwrap(); metrics::with_local_recorder(&recorder, || { diff --git a/bin/debug-trace-server/src/rpc_service.rs b/bin/debug-trace-server/src/rpc_service.rs index dc2155cb..f17a5291 100644 --- a/bin/debug-trace-server/src/rpc_service.rs +++ b/bin/debug-trace-server/src/rpc_service.rs @@ -20,6 +20,7 @@ use stateless_core::chain_spec::ChainSpec; use tracing::{trace, warn}; use crate::{ + admission::{AdmissionError, AdmissionLimiter, ExecutionPermit, TraceWeight}, data_provider::{ BlockData, DataProvider, DataProviderError, SLOW_STAGE_THRESHOLD_MS, TimeoutStage, }, @@ -167,6 +168,10 @@ pub struct RpcContext { response_cache: Option, /// Watch dog for tracking in-flight requests. watch_dog: RpcWatchDog, + /// Inbound admission gate (`None` = disabled, every request executes immediately). + admission: Option>, + /// Cap on a single serialized reply body (`--max-response-size`). + max_response_size: usize, } impl RpcContext { @@ -175,8 +180,17 @@ impl RpcContext { data_provider: Arc, chain_spec: Arc, response_cache: Option, + admission: Option>, + max_response_size: usize, ) -> Self { - Self { data_provider, chain_spec, response_cache, watch_dog: RpcWatchDog::new() } + Self { + data_provider, + chain_spec, + response_cache, + watch_dog: RpcWatchDog::new(), + admission, + max_response_size, + } } /// Returns a reference to the watch dog for spawning the checker task. @@ -235,6 +249,7 @@ impl RpcContext { method: &'static str, resource: CachedResource, variant: Option, + weight: TraceWeight, block_number: BlockNumberOrTag, start: Instant, ) -> Result { @@ -266,6 +281,12 @@ impl RpcContext { return Ok(BlockLookup::Cached(cached)); } + // Past the cache: this request is going to fetch and replay a block, so it needs an + // execution permit. Acquired *here* rather than at the gate so a cache hit — which + // costs microseconds — is never queued behind cold traces, and so the wait sits + // inside the deadline minted above instead of on top of it. + let permit = self.acquire_execution(method, weight, deadline).await?; + let t2 = Instant::now(); let data = self .data_provider @@ -288,7 +309,27 @@ impl RpcContext { ); } - Ok(BlockLookup::Fetched(data)) + Ok(BlockLookup::Fetched(data, permit)) + } + + /// Waits for an execution permit, or refuses when the wait would outlast the budget. + /// + /// `deadline` must be the same one the request's fetch will run under, so the wait is + /// carved out of that budget rather than added on top of it. + /// + /// `Ok(None)` means admission control is disabled for this process. + async fn acquire_execution( + &self, + method: &'static str, + weight: TraceWeight, + deadline: Instant, + ) -> Result, jsonrpsee::types::ErrorObjectOwned> { + let Some(limiter) = &self.admission else { return Ok(None) }; + let cutoff = self.data_provider.permit_cutoff(deadline); + match limiter.acquire_execution(method, weight.is_heavy(), cutoff).await { + Ok(permit) => Ok(Some(permit)), + Err(AdmissionError::Overloaded) => Err(overloaded_err(method)), + } } /// Runs the geth-style block-trace executor over `data` via [`compute_block_trace`] — @@ -299,7 +340,7 @@ impl RpcContext { method: &'static str, opts: GethDebugTracingOptions, ) -> Result { - compute_block_trace(data, method, || { + compute_block_trace(data, method, self.max_response_size, || { crate::tracing_executor::trace_block( &self.chain_spec, &data.block, @@ -317,7 +358,7 @@ enum BlockLookup { /// Served straight from the response cache. Cached(RawJson), /// Cache miss: block data fetched by the resolved canonical hash, ready to trace. - Fetched(Arc), + Fetched(Arc, Option), } // Error Helpers @@ -348,14 +389,29 @@ fn invalid_params_err(msg: String) -> jsonrpsee::types::ErrorObjectOwned { fn classify_and_gate( method_name: &'static str, opts: &GethDebugTracingOptions, -) -> Result, jsonrpsee::types::ErrorObjectOwned> { +) -> Result<(Option, TraceWeight), jsonrpsee::types::ErrorObjectOwned> { let shape = RequestShape::classify(opts); metrics::record_request_shape(method_name, shape.label()); if let RequestShape::InvalidTracerConfig { label, error } = &shape { metrics::record_rpc_error(method_name, ErrorReason::InvalidParams); return Err(invalid_params_err(format!("invalid tracerConfig for {label}: {error}"))); } - Ok(shape.cache_variant()) + Ok((shape.cache_variant(), shape.weight())) +} + +/// Renders an admission refusal raised *after* the handler recorded its arrival. +/// +/// Only the outcome side is recorded here: the arrival is the handler's own shape, already +/// counted at entry, so the identity closes with `reason="overloaded"` alone. The +/// middleware's own shed — the one that happens before any handler runs — records both +/// sides itself through `metrics::record_admission_shed`. +fn overloaded_err(method: &'static str) -> jsonrpsee::types::ErrorObjectOwned { + metrics::record_rpc_error(method, ErrorReason::Overloaded); + jsonrpsee::types::ErrorObjectOwned::owned( + crate::admission::QUEUE_FULL_CODE, + crate::admission::QUEUE_FULL_MESSAGE, + None::<()>, + ) } /// Maps a [`DataProviderError`] to a JSON-RPC error object. @@ -416,6 +472,7 @@ fn data_provider_failure( fn compute_block_trace( data: &BlockData, method_name: &'static str, + max_response_size: usize, run: impl FnOnce() -> Result, ) -> Result { let start = Instant::now(); @@ -428,6 +485,11 @@ fn compute_block_trace( let json = RawJson::try_new(&results) .map_err(|e| TraceError::Request(format!("Serialization failed: {e}")))?; + // Request-attributable, not data-attributable: the block is fine, the client asked for + // more output than this process will hand back. That discriminant is what keeps an + // oversized request from evicting a perfectly good block from the data cache. + let json = check_response_size(json, method_name, max_response_size) + .map_err(|e| TraceError::Request(e.to_string()))?; let serialize_ms = start.elapsed().as_millis() - trace_ms; let response_size = json.byte_len(); @@ -518,15 +580,67 @@ fn insert_cache( fn serialize_reply( result: &T, method_name: &'static str, + max_response_size: usize, ) -> RpcResult { let json = RawJson::try_new(result).map_err(|e| { metrics::record_rpc_error(method_name, ErrorReason::Internal); rpc_err(format!("Serialization failed: {e}")) })?; + let json = check_response_size(json, method_name, max_response_size).map_err(|e| { + // `TraceFailed` rather than `Internal`: the tracer ran and its output could not be + // returned, which is exactly what that reason means. `Internal` stays "our fault". + metrics::record_rpc_error(method_name, ErrorReason::TraceFailed); + rpc_err(e.to_string()) + })?; ResponseSizeMetrics::new_for_method(method_name).record(json.byte_len()); Ok(json) } +/// Discards a reply body that exceeds `--max-response-size`. +/// +/// The body has necessarily been built by the time it can be measured, so this does not +/// prevent the peak allocation of any one response. What it prevents is that body being +/// copied again into the JSON-RPC envelope and — for a batch entry — retained there until +/// every sibling entry finishes: it is that accumulation across a batch, not any single +/// response, that has previously exhausted this process's memory. Dropping here also keeps +/// the body out of the response cache, since the caller errors out before inserting. +fn check_response_size( + json: RawJson, + method_name: &'static str, + max_response_size: usize, +) -> Result { + let bytes = json.byte_len(); + if bytes <= max_response_size { + return Ok(json); + } + drop(json); + metrics::record_response_oversized(method_name); + warn!( + method = method_name, + response_bytes = bytes, + max_response_size, + "discarded a response over the configured size limit" + ); + Err(ResponseTooLarge { bytes, max_response_size }) +} + +/// The over-limit rejection, rendered once so both serialization points word it identically. +struct ResponseTooLarge { + bytes: usize, + max_response_size: usize, +} + +impl std::fmt::Display for ResponseTooLarge { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "response of {} bytes exceeds the {}-byte limit; use a lighter tracer, or request \ + fewer blocks per batch", + self.bytes, self.max_response_size + ) + } +} + /// Records metrics and logs for a completed request. fn record_request_completion(method_name: &'static str, block_num: u64, start: Instant) { let total_ms = start.elapsed().as_secs_f64() * 1000.0; @@ -557,20 +671,21 @@ impl DebugTraceRpcServer for RpcContext { .start_request(METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, format!("{block_number}")); let start = Instant::now(); let opts = opts.unwrap_or_default(); - let variant = classify_and_gate(METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, &opts)?; + let (variant, weight) = classify_and_gate(METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, &opts)?; - let data = match self + let (data, _permit) = match self .lookup_block_by_number( METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, CachedResource::DebugTraceBlock, variant, + weight, block_number, start, ) .await? { BlockLookup::Cached(cached) => return Ok(cached), - BlockLookup::Fetched(data) => data, + BlockLookup::Fetched(data, permit) => (data, permit), }; let result = self.compute_debug_trace(&data, METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, opts)?; @@ -602,7 +717,7 @@ impl DebugTraceRpcServer for RpcContext { self.watch_dog.start_request(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, format!("{block_hash}")); let start = Instant::now(); let opts = opts.unwrap_or_default(); - let variant = classify_and_gate(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, &opts)?; + let (variant, weight) = classify_and_gate(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, &opts)?; // Check cache — the requested hash IS the key; no resolution step. if let Some(cached) = check_cache( @@ -616,9 +731,16 @@ impl DebugTraceRpcServer for RpcContext { return Ok(cached); } + // Minted once and used for both the permit wait and the fetch, so the queue is carved + // out of the request's budget rather than added on top of it — total client latency + // stays bounded by `--block-fetch-timeout` however long the wait was. + let deadline = self.data_provider.fetch_deadline(); + let _permit = + self.acquire_execution(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, weight, deadline).await?; + let data = self .data_provider - .get_block_data_by_hash(block_hash) + .get_block_data_by_hash(block_hash, deadline) .await .map_err(|e| data_provider_failure(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, &e))?; let block_num = data.block.header.number; @@ -651,11 +773,16 @@ impl DebugTraceRpcServer for RpcContext { let opts = opts.unwrap_or_default(); // Shape metric + malformed-config rejection; tx-level responses are not cached, so // the cache variant itself is unused. - let _ = classify_and_gate(METHOD_DEBUG_TRACE_TRANSACTION, &opts)?; + let (_, weight) = classify_and_gate(METHOD_DEBUG_TRACE_TRANSACTION, &opts)?; + + // One deadline for the wait and the fetch; see `trace_block_by_hash`. + let deadline = self.data_provider.fetch_deadline(); + let _permit = + self.acquire_execution(METHOD_DEBUG_TRACE_TRANSACTION, weight, deadline).await?; let (data, tx_index) = self .data_provider - .get_block_data_for_tx(tx_hash) + .get_block_data_for_tx(tx_hash, deadline) .await .map_err(|e| data_provider_failure(METHOD_DEBUG_TRACE_TRANSACTION, &e))?; @@ -680,7 +807,8 @@ impl DebugTraceRpcServer for RpcContext { // Serialize before counting the request as served: a failure records an error, // and one request must land in exactly one bucket. - let json = serialize_reply(&result, METHOD_DEBUG_TRACE_TRANSACTION)?; + let json = + serialize_reply(&result, METHOD_DEBUG_TRACE_TRANSACTION, self.max_response_size)?; let elapsed = start.elapsed(); metrics::record_rpc_request(METHOD_DEBUG_TRACE_TRANSACTION, elapsed.as_secs_f64()); @@ -745,21 +873,22 @@ impl TraceRpcServer for RpcContext { metrics::record_request_shape(METHOD_TRACE_BLOCK, "default"); // `trace_block` takes no tracer options, so its variant is always `Default`. - let data = match self + let (data, _permit) = match self .lookup_block_by_number( METHOD_TRACE_BLOCK, CachedResource::TraceBlock, Some(ResponseVariant::Default), + TraceWeight::Normal, block_number, start, ) .await? { BlockLookup::Cached(cached) => return Ok(cached), - BlockLookup::Fetched(data) => data, + BlockLookup::Fetched(data, permit) => (data, permit), }; - let result = compute_block_trace(&data, METHOD_TRACE_BLOCK, || { + let result = compute_block_trace(&data, METHOD_TRACE_BLOCK, self.max_response_size, || { crate::tracing_executor::parity_trace_block( &self.chain_spec, &data.block, @@ -792,31 +921,40 @@ impl TraceRpcServer for RpcContext { // response here would count against a zero arrival side. metrics::record_request_shape(METHOD_TRACE_TRANSACTION, "default"); + // Refused capacity is surfaced as a real error, never degraded to the `null` below: + // a client that reads `null` learns "no such transaction" and does not back off. + // One deadline for the wait and the fetch; see `trace_block_by_hash`. + let deadline = self.data_provider.fetch_deadline(); + let _permit = + self.acquire_execution(METHOD_TRACE_TRANSACTION, TraceWeight::Normal, deadline).await?; + // Return null instead of error when tx not found or unreachable (matches mega-reth); // surface genuine Internal failures as -32000. Branches on the typed variant so any // future `DataProviderError` addition must be classified explicitly at compile time. - let (data, tx_index) = match self.data_provider.get_block_data_for_tx(tx_hash).await { - Ok(result) => result, - Err( - e @ (DataProviderError::TransactionNotFound(_) | - DataProviderError::TransactionPending(_) | - DataProviderError::Timeout { .. }), - ) => { - // A null result is still a served request — count it as one, and keep - // the degraded cause visible on its own counter. - metrics::record_null_result(METHOD_TRACE_TRANSACTION, error_reason(&e)); - metrics::record_rpc_request( - METHOD_TRACE_TRANSACTION, - start.elapsed().as_secs_f64(), - ); - return Ok(RawJson::null()); - } - Err( - e @ (DataProviderError::Internal(_) | DataProviderError::UnsupportedBlockTag(_)), - ) => { - return Err(data_provider_failure(METHOD_TRACE_TRANSACTION, &e)); - } - }; + let (data, tx_index) = + match self.data_provider.get_block_data_for_tx(tx_hash, deadline).await { + Ok(result) => result, + Err( + e @ (DataProviderError::TransactionNotFound(_) | + DataProviderError::TransactionPending(_) | + DataProviderError::Timeout { .. }), + ) => { + // A null result is still a served request — count it as one, and keep + // the degraded cause visible on its own counter. + metrics::record_null_result(METHOD_TRACE_TRANSACTION, error_reason(&e)); + metrics::record_rpc_request( + METHOD_TRACE_TRANSACTION, + start.elapsed().as_secs_f64(), + ); + return Ok(RawJson::null()); + } + Err( + e + @ (DataProviderError::Internal(_) | DataProviderError::UnsupportedBlockTag(_)), + ) => { + return Err(data_provider_failure(METHOD_TRACE_TRANSACTION, &e)); + } + }; let evm_start = Instant::now(); let result = crate::tracing_executor::parity_trace_transaction( @@ -834,7 +972,7 @@ impl TraceRpcServer for RpcContext { // Serialize before counting the request as served: a failure records an error, // and one request must land in exactly one bucket. - let json = serialize_reply(&result, METHOD_TRACE_TRANSACTION)?; + let json = serialize_reply(&result, METHOD_TRACE_TRANSACTION, self.max_response_size)?; let elapsed = start.elapsed(); metrics::record_rpc_request(METHOD_TRACE_TRANSACTION, elapsed.as_secs_f64()); @@ -1075,7 +1213,171 @@ mod tests { Duration::from_secs(1), 1024, )); - RpcContext::new(provider, Arc::new(chain_spec), response_cache) + RpcContext::new(provider, Arc::new(chain_spec), response_cache, None, usize::MAX) + } + + /// An over-limit body is discarded and counted, not returned. + /// + /// The cap cannot prevent the first allocation — the body has to exist before it can be + /// measured — so what it buys is that this body is never copied again into the JSON-RPC + /// envelope, nor retained by a batch until its siblings finish. That accumulation, not any + /// single response, is what has previously exhausted this process's memory. + #[test] + fn oversized_response_is_discarded() { + let body = serde_json::json!({ "trace": "x".repeat(4096) }); + let serialized = RawJson::try_new(&body).expect("serialize").byte_len(); + + let ok = serialize_reply(&body, METHOD_DEBUG_TRACE_TRANSACTION, serialized) + .expect("exactly at the limit is allowed"); + assert_eq!(ok.byte_len(), serialized); + + let err = serialize_reply(&body, METHOD_DEBUG_TRACE_TRANSACTION, serialized - 1) + .expect_err("one byte over is refused"); + assert_eq!(err.code(), ERROR_CODE_INTERNAL); + assert!(err.message().contains("exceeds"), "the message must say why: {}", err.message()); + assert!( + err.message().contains("lighter tracer"), + "and what to do about it: {}", + err.message() + ); + } + + /// An over-limit block trace is request-attributable, never data-attributable. + /// + /// The discriminant matters: `TraceError::Data` drops the block from the block-data cache, + /// and a client asking for too much output is no reason to evict a perfectly good block + /// that other requests are about to want. + #[test] + fn oversized_block_trace_is_request_attributable() { + let data = crate::data_provider::test_support::fixture_block_data(); + let body = serde_json::json!({ "trace": "x".repeat(4096) }); + let err = compute_block_trace(&data, METHOD_TRACE_BLOCK, 16, || Ok(body)) + .expect_err("over the limit"); + assert!( + matches!(err, TraceError::Request(_)), + "an oversized response must not evict the block that produced it" + ); + } + + /// The public module never learns an `admin_` method. This repository is public and this + /// port faces customers; the admin namespace lives on its own loopback listener. + #[test] + fn public_module_registers_no_admin_methods() { + let module = test_context(None, None, ChainSpec::default()) + .into_rpc_module() + .expect("the public module builds"); + let admin: Vec<_> = + module.method_names().filter(|name| name.starts_with("admin_")).collect(); + assert!(admin.is_empty(), "admin methods must not reach the public port: {admin:?}"); + } + + /// [`test_context`] with an admission gate installed. + fn admission_context( + response_cache: Option, + limiter: Arc, + ) -> RpcContext { + let mut ctx = test_context(None, response_cache, ChainSpec::default()); + ctx.admission = Some(limiter); + ctx + } + + /// A response-cache hit must not need an execution permit. + /// + /// This is the whole reason the permit is taken in the handler rather than at the gate: a + /// hit costs microseconds and no upstream call, so queueing it behind cold traces spends + /// availability to buy nothing. Here the gate's only permit is already held, and the hit + /// is still served. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn cache_hit_needs_no_execution_permit() { + let hash = B256::from([9u8; 32]); + let body = RawJson::try_new(&serde_json::json!({"cached": true})).expect("serialize"); + let cache = ResponseCache::new(ResponseCacheConfig::new(1_000_000, 100)); + cache.insert(CachedResource::DebugTraceBlock, hash, ResponseVariant::Default, &body); + + let limiter = AdmissionLimiter::new(1, 8, 1); + let _held = limiter + .acquire_execution( + METHOD_DEBUG_TRACE_BLOCK_BY_HASH, + false, + Instant::now() + Duration::from_secs(30), + ) + .await + .expect("the test holds the gate's only permit"); + + let ctx = admission_context(Some(cache), Arc::clone(&limiter)); + let served = ctx.trace_block_by_hash(hash, None).await.expect("a hit is served"); + assert!(served.shares_bytes_with(&body), "the cached bytes came back verbatim"); + assert_eq!(limiter.executing(), 1, "the hit took no permit of its own"); + } + + /// A request that cannot get a permit before its budget runs out is refused, not started. + /// + /// The distinction the gate exists for: the client sees a retryable `-32013` rather than + /// waiting out the deadline for a `-32001` it could have been told about immediately. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn permit_wait_past_the_budget_is_refused_not_timed_out() { + let limiter = AdmissionLimiter::new(1, 8, 1); + let _held = limiter + .acquire_execution( + METHOD_DEBUG_TRACE_BLOCK_BY_HASH, + false, + Instant::now() + Duration::from_secs(30), + ) + .await + .expect("the test holds the gate's only permit"); + + let ctx = admission_context(None, Arc::clone(&limiter)); + let started = Instant::now(); + let err = ctx + .trace_block_by_hash(B256::from([3u8; 32]), None) + .await + .expect_err("no permit is available and none will be"); + assert_eq!(err.code(), crate::admission::QUEUE_FULL_CODE); + assert_eq!(err.message(), crate::admission::QUEUE_FULL_MESSAGE); + assert!(started.elapsed() < Duration::from_secs(5), "refused promptly, not timed out"); + } + + /// Only the memory-hungry shapes pay the heavy sub-cap. + #[test] + fn heavy_shapes_are_the_ones_that_can_exhaust_memory() { + use alloy_rpc_types_trace::geth::{ + GethDebugBuiltInTracerType, GethDebugTracerType, GethDefaultTracingOptions, + }; + + let weight_of = |opts: &GethDebugTracingOptions| RequestShape::classify(opts).weight(); + let builtin = |tracer| GethDebugTracingOptions { + tracer: Some(GethDebugTracerType::BuiltInTracer(tracer)), + ..Default::default() + }; + + assert_eq!( + weight_of(&GethDebugTracingOptions::default()), + TraceWeight::Heavy, + "no tracer means the struct logger, which emits a record per executed opcode" + ); + assert_eq!( + weight_of(&builtin(GethDebugBuiltInTracerType::CallTracer)), + TraceWeight::Normal + ); + assert_eq!( + weight_of(&builtin(GethDebugBuiltInTracerType::FourByteTracer)), + TraceWeight::Normal + ); + assert_eq!( + weight_of(&builtin(GethDebugBuiltInTracerType::PreStateTracer)), + TraceWeight::Heavy, + "a prestate trace over a large block is the shape that has OOM-killed this server" + ); + // A struct-logger request with non-default flags bypasses the cache, so its size is + // bounded by nothing we can see up front. + let flagged = GethDebugTracingOptions { + config: GethDefaultTracingOptions { + disable_storage: Some(false), + ..Default::default() + }, + ..Default::default() + }; + assert_eq!(weight_of(&flagged), TraceWeight::Heavy); } /// [`test_context`] with the block-data cache merely toggled, for the cache-status @@ -1211,7 +1513,7 @@ mod tests { "tracerConfig": {"onlyTopCall": true}, })) .unwrap(); - assert!(classify_and_gate("test_method", &opts).unwrap().is_some()); + assert!(classify_and_gate("test_method", &opts).unwrap().0.is_some()); } #[test] From 7cd41340b6cb83cce24f1e78d0b453819114b54e Mon Sep 17 00:00:00 2001 From: "liquan.eth" Date: Sat, 22 Aug 2026 19:47:04 +0800 Subject: [PATCH 2/4] fix(debug-trace-server): bound the heavy class's share of the admitted budget MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three findings from the Codex review of #188, all reproduced before fixing. The admitted budget is class-blind by design — the gate runs before anything parses the tracer — so heavy requests were admitted against `max_queue + max_concurrent` and then bottlenecked on a sub-cap a fraction of its size. A flood of them filled the budget while barely executing: reproduced with 12 heavy requests against a 12-slot gate, where 1 executed, 3 execution permits sat idle, and an ordinary request was refused. That is a priority inversion handed to whoever sends the most expensive shape, in the feature meant to prevent exactly that. Heavy requests now get their own share — they may queue in the same proportion to their execution budget as the process as a whole — which also makes `--admission-max-queue 0` mean execute-or-shed for them, where a share of the shared budget let 632 of them wait at the defaults. The heavy occupancy gauge was raised only once both permits were in hand, so it read zero while every sub-cap permit was reserved and further heavy requests were blocked on them — disagreeing with the admin RPC, which counted them immediately. It is now raised by a guard at acquisition, the same shape the ordinary occupancy counter already uses. `--max-batch-response-size` was allowed to equal `--max-response-size`, but our own check measures the bare body while the framework's cap measures the envelope and client `id` too. A body that just passed ours could still be swapped for an oversized-response error after the handler had counted the request as served, and without incrementing the oversized counter. Startup now requires headroom between the two caps and names why, and the framework-swapped case is counted on `debug_trace_response_oversized_total` so that series is complete either way. Both heavy-budget regressions were mutation-tested: restoring the shared budget fails them, and the zero-queue case asserts promptness rather than outcome, since the old behaviour also ended in `Overloaded` — just after parking until the deadline, which is the queueing that configuration says it does not want. Co-Authored-By: Claude Opus 5 (1M context) --- AGENTS.md | 2 +- README.md | 1 + bin/debug-trace-server/src/admission.rs | 184 ++++++++++++++++++- bin/debug-trace-server/src/main.rs | 36 +++- bin/debug-trace-server/src/rpc_middleware.rs | 6 +- 5 files changed, 209 insertions(+), 20 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 0af66393..0878676a 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -112,7 +112,7 @@ Inbound JSON-RPC batch entries execute concurrently as independent runtime tasks Inbound admission control (`admission.rs`) bounds what clients may ask of the process — every other concurrency cap here is outbound, and unbounded inline EVM tracing otherwise starves chain sync, the accept loop and the metrics exporter along with the requests — shedding with `-32013 "Request queue is full"`, mega-reth's `ConcurrencyLimiter` contract byte for byte so existing client backoff applies unchanged. It is deliberately split in two: `AdmissionLayer` (installed *inside* `ConcurrentBatchLayer`, so it sees single calls and every batch entry, since that layer decomposes batches into per-entry `call`s rather than delegating to an inner `batch`) only ever runs a non-blocking CAS against `--admission-max-concurrent` + `--admission-max-queue`, while the execution permit is taken in the handler *after* `check_cache` misses. That placement is load-bearing, not stylistic: `CancelGuard` arms on a request's first poll and the handler records its arrival synchronously in that same poll, so a middleware gate that parked before the handler would record a cancellation with no matching arrival for every client that hung up while queued — negative, permanent identity drift, worst under exactly the overload the gate exists for; a layer that only CAS-es preserves the invariant by construction, and the permit wait then sits after the arrival is already booked. -It also means a response-cache hit never takes a permit, the typed `RequestShape` is already in hand so the heavy-tracer sub-cap (`--admission-heavy-max-concurrent`, covering `prestateTracer`/JS/`muxTracer` and *every* struct-logger request including the bare default — the flags separating the two struct-logger shapes change output size, not kind — taken *before* the ordinary permit, so heavy requests never occupy execution permits while waiting for each other) costs no second parse of attacker-controlled JSON, and what the permits count is blocks actually being fetched and replayed. +It also means a response-cache hit never takes a permit, the typed `RequestShape` is already in hand so the heavy-tracer sub-cap (`--admission-heavy-max-concurrent`, covering `prestateTracer`/JS/`muxTracer` and *every* struct-logger request including the bare default — the flags separating the two struct-logger shapes change output size, not kind — taken *before* the ordinary permit, so heavy requests never occupy execution permits while waiting for each other, and bounded by their own share of the admitted budget — `heavy_max_concurrent x (1 + max_queue / max_concurrent)` — because the gate itself is class-blind, so without it a heavy flood fills the admitted budget while blocking on a sub-cap a fraction of its size and ordinary traffic is shed with most execution permits idle) costs no second parse of attacker-controlled JSON, and what the permits count is blocks actually being fetched and replayed. The permit wait is clamped to `deadline - witness_timeout` (`DataProvider::permit_cutoff`), so a request that queued away the budget its witness fetch still needs is refused now rather than started and timed out later — the difference between "may reject" and "times out"; the reserve falls back to half the budget when `--witness-timeout` does not fit inside `--block-fetch-timeout` (a legal pair, since the witness sub-deadline is a `min` against the outer one), because reserving all of it would leave a zero-length wait and silently reduce `--admission-max-queue` to a no-op. Every handler mints its deadline once and passes it to both the permit wait and the fetch (`get_block_data_by_hash`/`get_block_data_for_tx` take it as a parameter for exactly this reason), so the queue is carved out of `--block-fetch-timeout` rather than added on top of it. `debug_getCacheStatus` and its `timed_` alias are the sole exemption (matched on the `timed_`-stripped name, since the gateway adds that prefix by default and a bare-name comparison would never match production traffic); `assert_admission_covers_module` fails startup if a newly registered method escapes `metrics::GATED_METHODS`. diff --git a/README.md b/README.md index 7cb0bf5c..65f36168 100644 --- a/README.md +++ b/README.md @@ -131,6 +131,7 @@ The defaults sit above the highest occupancy this server has been measured servi Memory-hungry tracers additionally pass `--admission-heavy-max-concurrent`, a much smaller budget: one such response has been measured near a gigabyte. That set is `prestateTracer`, JS tracers, `muxTracer`, and **every struct-logger request** — both the bare default (a `debug_trace*` call with no `tracer`) and one with non-default flags, since the flags change the size of that output rather than its kind, and a struct logger emits a record per executed opcode. Note the consequence: an opts-less `debug_traceBlockByNumber` is a heavy request, so a client that sends no tracer is limited to `--admission-heavy-max-concurrent` at a time; raise that flag if such traffic is a normal part of your workload. +Heavy requests also get their own share of the admitted budget — they may queue in the same proportion to their execution budget as the process as a whole — so a flood of them is refused at that share rather than filling the class-blind admitted budget and shedding ordinary traffic that has idle permits waiting. Startup logs both `heavy_max_concurrent x max_response_size` and `max_concurrent x max_response_size` — the first bounds the shapes that can actually reach the response cap, the second is the theoretical ceiling if every admitted request returned a maximal body — so they can be checked against the host's memory limit. Neither covers a tracer's *intermediate* allocations, which nothing here bounds; a per-transaction-count gate would be needed for that and is not implemented. Watch `debug_trace_rpc_errors_total{reason="overloaded"}` for shedding, `debug_trace_admission_in_flight` / `debug_trace_admission_executing` for occupancy (queue depth is their difference), and the `debug_trace_admission_max_*` gauges for what is actually in effect, since the limits are changeable at runtime. diff --git a/bin/debug-trace-server/src/admission.rs b/bin/debug-trace-server/src/admission.rs index 062172c5..30f142ff 100644 --- a/bin/debug-trace-server/src/admission.rs +++ b/bin/debug-trace-server/src/admission.rs @@ -248,6 +248,13 @@ pub(crate) struct AdmissionLimiter { execution: Arc, /// A smaller budget the memory-hungry tracer shapes must pass first. heavy: Arc, + /// Heavy requests that have reached the permit stage and not yet finished. + /// + /// Bounded separately from `in_flight` because the two have different bottlenecks. The + /// admitted budget is class-blind by design — the gate runs before anything parses the + /// tracer — so without this a flood of heavy requests fills it while blocking on a sub-cap + /// a fraction of its size, and ordinary traffic is shed with most execution permits idle. + heavy_in_flight: AtomicUsize, } impl AdmissionLimiter { @@ -259,6 +266,7 @@ impl AdmissionLimiter { max_queue: AtomicU64::new(max_queue), execution: Arc::new(ResizableSemaphore::new(max_concurrent)), heavy: Arc::new(ResizableSemaphore::new(heavy_max_concurrent)), + heavy_in_flight: AtomicUsize::new(0), }); limiter.publish_limits(); limiter @@ -272,6 +280,18 @@ impl AdmissionLimiter { self.max_queue.load(Ordering::Relaxed).saturating_add(self.execution.limit()) } + /// How many heavy requests may be at the permit stage at once. + /// + /// The heavy class is allowed to queue in the same proportion to its execution budget as + /// the process as a whole — `max_queue / max_concurrent` waiters per slot — so it can + /// absorb a burst without being able to crowd ordinary traffic out of admission. It also + /// makes `--admission-max-queue 0` mean execute-or-shed for heavy requests too, which a + /// share of the shared budget did not. + fn heavy_capacity(&self) -> u64 { + let queue_per_slot = self.max_queue() / self.execution.limit().max(1); + self.heavy.limit().saturating_mul(queue_per_slot.saturating_add(1)) + } + pub(crate) fn max_concurrent(&self) -> u64 { self.execution.limit() } @@ -362,7 +382,9 @@ impl AdmissionLimiter { /// /// A heavy shape takes the sub-cap permit *first*. Acquiring it second would let heavy /// requests occupy execution permits while waiting for each other, starving ordinary - /// traffic behind work that is not running. + /// traffic behind work that is not running. It is also refused outright once the heavy + /// class already holds its share of the budget, rather than joining a queue that only its + /// own sub-cap drains — see [`Self::heavy_capacity`]. pub(crate) async fn acquire_execution( self: &Arc, method: &'static str, @@ -370,17 +392,40 @@ impl AdmissionLimiter { cutoff: Instant, ) -> Result { let started = Instant::now(); - let heavy_permit = if heavy { Some(acquire_by(&self.heavy, cutoff).await?) } else { None }; + let heavy_permit = if heavy { + let _slot = self.enter_heavy()?; + let permit = HeavyPermit::new(acquire_by(&self.heavy, cutoff).await?); + Some((permit, _slot)) + } else { + None + }; let permit = acquire_by(&self.execution, cutoff).await?; metrics::record_admission_permit_wait(started.elapsed().as_secs_f64()); let gauges = AdmissionMetrics::new_for_method(method); gauges.executing_delta(1.0); - if heavy_permit.is_some() { - metrics::record_admission_heavy_delta(1.0); - } Ok(ExecutionPermit { _permit: permit, heavy: heavy_permit, gauges }) } + + /// Claims one of the heavy class's slots, or refuses when it already holds its share. + fn enter_heavy(self: &Arc) -> Result { + let capacity = self.heavy_capacity(); + let mut current = self.heavy_in_flight.load(Ordering::Relaxed); + loop { + if current as u64 >= capacity { + return Err(AdmissionError::Overloaded); + } + match self.heavy_in_flight.compare_exchange_weak( + current, + current + 1, + Ordering::Acquire, + Ordering::Relaxed, + ) { + Ok(_) => return Ok(HeavySlot { limiter: Arc::clone(self) }), + Err(actual) => current = actual, + } + } + } } /// Acquires one permit, giving up at `cutoff`. @@ -398,6 +443,41 @@ async fn acquire_by( Ok(DebtAwarePermit { permit: Some(permit), owner: Arc::clone(semaphore) }) } +/// Holds one of the heavy class's share of the admitted budget. +pub(crate) struct HeavySlot { + limiter: Arc, +} + +impl Drop for HeavySlot { + fn drop(&mut self) { + self.limiter.heavy_in_flight.fetch_sub(1, Ordering::Release); + } +} + +/// A heavy sub-cap permit, counted on the occupancy gauge for as long as it is held. +/// +/// The gauge is raised here rather than once *both* permits are in hand, so it cannot read +/// zero while every heavy permit is reserved and further heavy requests are blocked on them — +/// the state an operator is most likely to be staring at. Raised at the same moment the +/// limiter's own counter is, so the Prometheus view and the admin RPC cannot disagree. +struct HeavyPermit { + /// Held for its `Drop`, which returns the sub-cap permit. + _permit: DebtAwarePermit, +} + +impl HeavyPermit { + fn new(permit: DebtAwarePermit) -> Self { + metrics::record_admission_heavy_delta(1.0); + Self { _permit: permit } + } +} + +impl Drop for HeavyPermit { + fn drop(&mut self) { + metrics::record_admission_heavy_delta(-1.0); + } +} + /// Holds one unit of admitted capacity for the whole request. pub(crate) struct InFlightGuard { limiter: Arc, @@ -412,19 +492,22 @@ impl Drop for InFlightGuard { } /// Holds the right to fetch and replay one block. -#[derive(Debug)] pub(crate) struct ExecutionPermit { _permit: DebtAwarePermit, - heavy: Option, + /// The sub-cap permit and the budget slot, both released with this one. + heavy: Option<(HeavyPermit, HeavySlot)>, gauges: AdmissionMetrics, } +impl std::fmt::Debug for ExecutionPermit { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.debug_struct("ExecutionPermit").field("heavy", &self.heavy.is_some()).finish() + } +} + impl Drop for ExecutionPermit { fn drop(&mut self) { self.gauges.executing_delta(-1.0); - if self.heavy.is_some() { - metrics::record_admission_heavy_delta(-1.0); - } } } @@ -676,6 +759,87 @@ mod tests { ); } + /// A flood of heavy requests cannot crowd ordinary traffic out of admission. + /// + /// The regression this pins: the admitted budget is class-blind, so heavy requests used to + /// fill it while blocking on a sub-cap a fraction of its size. Twelve of them would take + /// all twelve admitted slots, one would execute, and an ordinary request was then shed with + /// three execution permits sitting idle — a priority inversion handed to whoever sends the + /// most expensive shape. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn a_heavy_flood_cannot_shed_ordinary_traffic() { + // 4 + 8 = 12 admitted; 4 execution permits; 1 heavy at a time, so heavy gets + // 1 * (1 + 8/4) = 3 of the budget. + let limiter = AdmissionLimiter::new(4, 8, 1); + assert_eq!(limiter.heavy_capacity(), 3); + + let mut admitted = Vec::new(); + let mut waiters = tokio::task::JoinSet::new(); + for _ in 0..12 { + admitted.push(limiter.try_admit(METHOD).expect("admitted by the class-blind gate")); + let limiter = Arc::clone(&limiter); + waiters.spawn(async move { limiter.acquire_execution(METHOD, true, far()).await }); + } + tokio::time::sleep(Duration::from_millis(100)).await; + + // One heavy request runs and two wait; the other nine were refused at the class gate + // instead of parking on a sub-cap only they can drain. + assert_eq!(limiter.heavy_executing(), 1); + assert!(limiter.heavy_in_flight.load(Ordering::Relaxed) <= 3); + + // Which is the point: an ordinary request still gets a permit, because the execution + // permits the heavy flood was not using are still reachable. + let ordinary = limiter + .acquire_execution(METHOD, false, far()) + .await + .expect("ordinary traffic is not starved by a heavy flood"); + drop(ordinary); + waiters.abort_all(); + } + + /// `--admission-max-queue 0` means execute-or-shed for heavy requests too. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn a_zero_queue_leaves_heavy_requests_nowhere_to_wait() { + let limiter = AdmissionLimiter::new(8, 0, 2); + assert_eq!(limiter.heavy_capacity(), 2, "no queue means no heavy waiters either"); + + let _first = limiter.acquire_execution(METHOD, true, far()).await.expect("first heavy"); + let _second = limiter.acquire_execution(METHOD, true, far()).await.expect("second heavy"); + let started = Instant::now(); + let refused = limiter.acquire_execution(METHOD, true, far()).await; + assert_eq!(refused.unwrap_err(), AdmissionError::Overloaded); + // Promptness is the assertion that discriminates: sharing the class-blind budget also + // ends in `Overloaded`, but only after parking on the sub-cap until the cutoff — which + // is the queueing this configuration says it does not want. + assert!( + started.elapsed() < Duration::from_secs(1), + "refused outright, not parked on a full sub-cap until the deadline" + ); + } + + /// The heavy occupancy gauge is raised the moment the sub-cap permit is taken, not once + /// both permits are in hand — otherwise it reads zero while every heavy permit is reserved + /// and further heavy requests are blocked on them, disagreeing with the admin RPC. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn heavy_occupancy_is_visible_while_waiting_for_an_execution_permit() { + let limiter = AdmissionLimiter::new(1, 8, 1); + let _blocker = limiter.acquire_execution(METHOD, false, far()).await.expect("blocker"); + + let waiting = { + let limiter = Arc::clone(&limiter); + tokio::spawn(async move { limiter.acquire_execution(METHOD, true, far()).await }) + }; + tokio::time::sleep(Duration::from_millis(100)).await; + + assert_eq!( + limiter.heavy_executing(), + 1, + "the sub-cap permit is held and must be visible as such, not only once the \ + execution permit follows" + ); + waiting.abort(); + } + /// Occupancy stays truthful while a shrink's debt is outstanding. /// /// The regression this pins: deriving `executing()` as `limit - available_permits` reports diff --git a/bin/debug-trace-server/src/main.rs b/bin/debug-trace-server/src/main.rs index 3a6854ec..4fda4bab 100644 --- a/bin/debug-trace-server/src/main.rs +++ b/bin/debug-trace-server/src/main.rs @@ -567,6 +567,16 @@ const DEFAULT_ADMISSION_MAX_QUEUE: u64 = 8192; /// this figure times `--max-response-size` is what to check against the host's memory limit. const DEFAULT_ADMISSION_HEAVY_MAX_CONCURRENT: u64 = 8; +/// How much room `--max-batch-response-size` must leave above `--max-response-size`. +/// +/// Our own check measures the bare result body; the framework's cap measures the whole +/// JSON-RPC response, envelope and client-supplied `id` included. Set the two caps equal and a +/// body that passes our check can still be swapped for an oversized-response error by the +/// framework — after the handler has already counted the request as served. Requiring this +/// much headroom keeps that swap out of reach for any sane `id`, and turns a config that would +/// have mis-accounted silently into a startup message. +const RESPONSE_ENVELOPE_HEADROOM: u64 = 64 * 1024; + /// Parses a human-readable size string into bytes. /// /// Accepts suffixes: `KB` (1024), `MB` (1024²), `GB` (1024³). Case-insensitive. @@ -708,14 +718,17 @@ fn validate_args(args: &Args) -> Result { ); } // The batch builder holds whole entry bodies, so a batch cap below one entry's cap could - // never assemble even a single maximal response. - if args.max_batch_response_size < args.max_response_size { + // never assemble even a single maximal response — and it must clear it by enough for the + // JSON-RPC envelope, or the framework can reject a body our own check just passed. + let required_batch_cap = args.max_response_size.saturating_add(RESPONSE_ENVELOPE_HEADROOM); + if args.max_batch_response_size < required_batch_cap { eyre::bail!( - "--max-batch-response-size ({}) must be at least --max-response-size ({}): a batch \ - holds whole entry bodies, so a smaller batch cap could not assemble even one \ - maximal entry", + "--max-batch-response-size ({}) must be at least --max-response-size ({}) plus {} \ + bytes of headroom: a batch holds whole entry bodies, and the framework's cap counts \ + the JSON-RPC envelope and request id that our own size check does not", args.max_batch_response_size, - args.max_response_size + args.max_response_size, + RESPONSE_ENVELOPE_HEADROOM ); } admin_bind_addr(args)?; @@ -1812,11 +1825,20 @@ mod tests { /// A batch holds whole entry bodies, so a batch cap under one entry's cap could never /// assemble even a single maximal response. #[test] - fn batch_response_cap_must_cover_one_response() { + fn batch_response_cap_must_cover_one_response_plus_its_envelope() { let args = parse_args(&["--max-response-size", "512MB", "--max-batch-response-size", "256MB"]); let err = validate_args(&args).expect_err("a batch cap below the entry cap").to_string(); assert!(err.contains("--max-batch-response-size"), "{err}"); + + // Equal caps are the trap: our own check measures the bare body while the framework's + // measures the envelope too, so a body that just passes ours can still be swapped for + // an oversized error after the handler counted the request as served. + let equal = + parse_args(&["--max-response-size", "512MB", "--max-batch-response-size", "512MB"]); + let err = validate_args(&equal).expect_err("equal caps leave no envelope room").to_string(); + assert!(err.contains("headroom"), "the error must explain why equal is not enough: {err}"); + assert!(validate_args(&parse_args(&["--max-response-size", "512MB"])).is_ok()); } diff --git a/bin/debug-trace-server/src/rpc_middleware.rs b/bin/debug-trace-server/src/rpc_middleware.rs index d4a35c2c..7d8b31b2 100644 --- a/bin/debug-trace-server/src/rpc_middleware.rs +++ b/bin/debug-trace-server/src/rpc_middleware.rs @@ -201,8 +201,10 @@ fn settle_response(rp: &MethodResponse, handler_reported: bool, guard: CancelGua // bound: an entry body that passes the per-response check can still push the // assembled batch past the framework's cap. The client-saw-error / // books-say-served mismatch is accepted like the other documented - // approximations. - Some(OVERSIZED_RESPONSE_CODE) => {} + // approximations — but the oversized counter is not part of the identity, so it + // is recorded here too rather than leaving these invisible to the one series an + // operator would alert on. + Some(OVERSIZED_RESPONSE_CODE) => crate::metrics::record_response_oversized(method), Some(_) => { crate::metrics::record_rpc_error(method, crate::metrics::ErrorReason::Unattributed) } From 558594ed1404c0f13d21f2e86dee0986a6b47e40 Mon Sep 17 00:00:00 2001 From: "liquan.eth" Date: Sat, 22 Aug 2026 21:39:19 +0800 Subject: [PATCH 3/4] fix(debug-trace-server): publish shrink debt before removing permits MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two more findings from the Codex re-review of #188; a third was refuted. Shrinking a saturated limiter recorded the debt only after `forget_permits` reported how little it could take. A release landing between the two observed zero debt, handed its permit back, and let a queued request through above the limit the shrink had just set — corrected only by a later release. Publishing the debt first inverts the window: a release now sees a debt that is at worst too large and forgets its permit, which is the conservative direction, and the part that could be removed immediately is cancelled afterwards. The accounting is unchanged in the quiescent case. The envelope headroom between `--max-batch-response-size` and `--max-response-size` was a fixed 64 KiB, which is a guess rather than a bound: the envelope's only unbounded part is the client-supplied `id`, and a client can pad one well past that. It is now derived from the request-body cap, which bounds the id outright, and that cap is pinned explicitly rather than inherited from the framework's default so the derivation cannot drift on an upgrade. Refuted: gating notifications. `RpcService::notification` answers without dispatching the method at all, so a notification reaches no handler, waits on no permit and does no work; gating one would spend capacity on nothing, and since a notification carries no response a shed could only be silent. Pinned by `a_notification_never_reaches_a_handler_or_takes_capacity`, which asserts the handler never runs and no capacity is taken even with the gate saturated. The new debt stress test guards end-state accounting — no permit lost to a double-forget, none conjured by a release that should have forgotten one — and is bounded by a timeout so a protocol that stops circulating permits fails red instead of hanging the job. It deliberately does not claim to pin the reordering above: the old ordering's defect is a transient over-admission that a quiescent invariant cannot observe, and it still passes under that mutation. Co-Authored-By: Claude Opus 5 (1M context) --- bin/debug-trace-server/src/admission.rs | 70 ++++++++++++++++++-- bin/debug-trace-server/src/main.rs | 19 ++++-- bin/debug-trace-server/src/rpc_middleware.rs | 51 ++++++++++++++ 3 files changed, 130 insertions(+), 10 deletions(-) diff --git a/bin/debug-trace-server/src/admission.rs b/bin/debug-trace-server/src/admission.rs index 30f142ff..9e10b34c 100644 --- a/bin/debug-trace-server/src/admission.rs +++ b/bin/debug-trace-server/src/admission.rs @@ -146,11 +146,16 @@ impl ResizableSemaphore { self.sem.add_permits((growth - cancelled) as usize); } } else if permits < previous { - let wanted = (previous - permits) as usize; - let removed = self.sem.forget_permits(wanted); - if removed < wanted { - self.debt.fetch_add((wanted - removed) as u64, Ordering::SeqCst); - } + let wanted = previous - permits; + // The debt is published *before* any permit is removed, and the part that could + // be removed immediately is cancelled after. A release landing in between then + // sees a debt that is at worst too large and forgets its permit — the + // conservative direction. Published after the removal instead, that same release + // would observe zero debt, hand its permit back, and let a queued request through + // above the limit the shrink just set. + self.debt.fetch_add(wanted, Ordering::SeqCst); + let removed = self.sem.forget_permits(wanted as usize) as u64; + self.cancel_debt(removed); } } @@ -840,6 +845,61 @@ mod tests { waiting.abort(); } + /// Resizing concurrently with acquire/release must not leak or duplicate permits. + /// + /// The debt protocol has two writers on the hot path (a release settling debt) and one on + /// the admin path (a resize), so its failure mode is drift rather than a crash: a permit + /// forgotten twice shrinks the budget permanently, one returned when it should have been + /// forgotten inflates it. Neither shows up until much later, so this asserts the books + /// balance exactly once everything quiesces. + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] + async fn concurrent_resizes_and_releases_keep_the_budget_exact() { + let limiter = AdmissionLimiter::new(8, 64, 8); + let mut tasks = tokio::task::JoinSet::new(); + for _ in 0..4 { + let limiter = Arc::clone(&limiter); + tasks.spawn(async move { + for _ in 0..200 { + if let Ok(permit) = limiter.acquire_execution(METHOD, false, far()).await { + tokio::task::yield_now().await; + drop(permit); + } + } + }); + } + { + let limiter = Arc::clone(&limiter); + tasks.spawn(async move { + for round in 0..200u64 { + limiter.set_max_concurrent(1 + round % 8); + tokio::task::yield_now().await; + } + }); + } + // Bounded: a protocol that loses permits starves every acquirer, and the failure would + // otherwise be a hung job rather than a red test. + let drain = async { + while let Some(joined) = tasks.join_next().await { + joined.expect("no task panicked"); + } + }; + tokio::time::timeout(Duration::from_secs(20), drain) + .await + .expect("permits stopped circulating — the debt protocol lost some"); + + // Quiesced: everything handed out came back, and the semaphore holds exactly the + // configured limit — no permit lost to a double-forget, none conjured by a release + // that should have forgotten one. + limiter.set_max_concurrent(8); + assert_eq!(limiter.executing(), 0, "every permit was returned"); + assert_eq!(limiter.execution.debt.load(Ordering::SeqCst), 0, "no debt outstanding"); + assert_eq!( + limiter.execution.sem.available_permits(), + 8, + "the budget is exactly the configured limit" + ); + } + /// Occupancy stays truthful while a shrink's debt is outstanding. /// /// The regression this pins: deriving `executing()` as `limit - available_permits` reports diff --git a/bin/debug-trace-server/src/main.rs b/bin/debug-trace-server/src/main.rs index 4fda4bab..824f2f70 100644 --- a/bin/debug-trace-server/src/main.rs +++ b/bin/debug-trace-server/src/main.rs @@ -567,15 +567,21 @@ const DEFAULT_ADMISSION_MAX_QUEUE: u64 = 8192; /// this figure times `--max-response-size` is what to check against the host's memory limit. const DEFAULT_ADMISSION_HEAVY_MAX_CONCURRENT: u64 = 8; +/// Cap on an inbound request body, pinned rather than left to the framework's default so the +/// envelope headroom below can be derived from it instead of guessed. +const MAX_REQUEST_BODY_SIZE: u32 = 10 * 1024 * 1024; + /// How much room `--max-batch-response-size` must leave above `--max-response-size`. /// /// Our own check measures the bare result body; the framework's cap measures the whole /// JSON-RPC response, envelope and client-supplied `id` included. Set the two caps equal and a /// body that passes our check can still be swapped for an oversized-response error by the -/// framework — after the handler has already counted the request as served. Requiring this -/// much headroom keeps that swap out of reach for any sane `id`, and turns a config that would -/// have mis-accounted silently into a startup message. -const RESPONSE_ENVELOPE_HEADROOM: u64 = 64 * 1024; +/// framework — after the handler has already counted the request as served. +/// +/// Derived rather than assumed: the only unbounded part of the envelope is the `id`, which the +/// client sends inside the request body, so [`MAX_REQUEST_BODY_SIZE`] bounds it outright. A +/// fixed guess would hold for sane ids and quietly fail for a client that pads one. +const RESPONSE_ENVELOPE_HEADROOM: u64 = MAX_REQUEST_BODY_SIZE as u64 + 1024; /// Parses a human-readable size string into bytes. /// @@ -1130,7 +1136,10 @@ async fn main() -> Result<()> { ); u32::MAX }); - let config = ServerConfig::builder().max_response_body_size(max_response_body_size).build(); + let config = ServerConfig::builder() + .max_response_body_size(max_response_body_size) + .max_request_body_size(MAX_REQUEST_BODY_SIZE) + .build(); // Order is load-bearing: the batch layer is outermost, so the admission layer below it // sees single calls *and* every batch entry. Reversed, an N-entry batch would pass the // gate as one unit — which is the traffic shape that has actually taken this server down. diff --git a/bin/debug-trace-server/src/rpc_middleware.rs b/bin/debug-trace-server/src/rpc_middleware.rs index 7d8b31b2..0803b730 100644 --- a/bin/debug-trace-server/src/rpc_middleware.rs +++ b/bin/debug-trace-server/src/rpc_middleware.rs @@ -768,6 +768,57 @@ mod tests { module } + /// A notification never reaches a handler, so it must not consume admission capacity. + /// + /// Pinned because the opposite is an inviting misreading: a JSON-RPC message with no `id` + /// looks like it should be gated like any other call. jsonrpsee answers it in + /// `RpcService::notification` without dispatching the method at all, so gating one would + /// spend a slot on work that never happens — and, since a notification cannot carry an + /// error response, shedding one could only be silent. + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn a_notification_never_reaches_a_handler_or_takes_capacity() { + use std::sync::atomic::{AtomicBool, Ordering}; + + static HANDLER_RAN: AtomicBool = AtomicBool::new(false); + HANDLER_RAN.store(false, Ordering::SeqCst); + + let mut module = RpcModule::new(()); + module + .register_async_method(crate::metrics::METHOD_TRACE_BLOCK, |_, _, _| async { + HANDLER_RAN.store(true, Ordering::SeqCst); + "ok" + }) + .unwrap(); + + // A gate with no capacity at all: anything that were gated would be shed. + let limiter = crate::admission::AdmissionLimiter::new(1, 0, 1); + let _held = limiter + .acquire_execution( + crate::metrics::METHOD_TRACE_BLOCK, + false, + Instant::now() + Duration::from_secs(30), + ) + .await + .expect("the test holds the only execution permit"); + let (addr, _handle) = + spawn_with_limits(module, 4, u32::MAX as usize, Some(Arc::clone(&limiter))).await; + + let body = post_text( + addr, + json!({"jsonrpc": "2.0", "method": "trace_block", "params": []}).to_string(), + ) + .await; + + // jsonrpsee answers a notification-only request with a bare `null` — no result, no + // error, nothing that could carry a shed. + assert!( + body.is_empty() || body == "null", + "a notification gets no real response: {body:?}" + ); + assert!(!HANDLER_RAN.load(Ordering::SeqCst), "the framework never dispatched the method"); + assert_eq!(limiter.in_flight(), 0, "and it never took a unit of admitted capacity"); + } + /// Every entry of a batch admits on its own account. /// /// This is the layer-order pin. `ConcurrentBatch` must sit *outside* the admission layer, From bd26e256ffb261cd01387e5eca3bb278c65c8a42 Mon Sep 17 00:00:00 2001 From: "liquan.eth" Date: Sun, 23 Aug 2026 13:34:56 +0800 Subject: [PATCH 4/4] refactor(debug-trace-server): dedup the admission seams found by /simplify MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Quality pass over #188 from four independent review angles (reuse, simplification, efficiency, altitude). No behaviour change; net -92 lines despite adding a helper, a test and docs. Gating is now derived rather than enumerated. `GATED_METHODS` was `ALL_METHODS` minus the cache-status endpoint, and `main.rs` carried a second `EXEMPT` list that also had to spell the `timed_` alias, so one fact lived in three places and a startup panic existed to police them. There is now a single `GATE_EXEMPT_METHODS`, `is_gated` derives from it, and the startup check asks something with independent value instead: whether a registered method is absent from `ALL_METHODS`, which would both ungate it and collapse its metrics onto `unknown`. The bounded compare-and-swap that admits a request was written twice, once per counter, with the memory orderings — the subtle part — copied. It is now one `try_claim`. `acquire_by` became an inherent method so the `checked_out` increment sits next to the decrement it pairs with. The rule that a gate must cover one batch's concurrent entries was enforced at startup and again on the admin setter, with independently worded messages. Both now call one predicate that takes each caller's spelling for the limits, the same shape and for the same reason as `stateless_common::R2Flag`. `TraceWeight` moved next to `RequestShape`, which produces it, so `response_cache` no longer imports from `admission`; the gate consumes the classification rather than owning it. `acquire_execution` takes the type instead of a `bool`, so the class survives to the mechanism and a future third class stays internal to `admission`. `trace_block_by_hash` open-coded the cache-check then permit then fetch sequence that `lookup_block_by_number` already encapsulates; it now goes through a by-hash sibling. The tx handlers keep their two inline lines deliberately — sharing them would need an error type spanning admission refusal and fetch failure just so the Parity path can keep degrading the latter to `null`, which is more machinery than it removes. Smaller: one construction site for the shed error (and `borrowed`, so the path that runs under strain allocates nothing); `admin` reuses the crate's `invalid_params_err`; the admin listener's three-deep send-and-return ladder became one `?` chain; `check_response_size` returns the message it already formatted instead of a struct existing to be stringified; `permit_reserve` is a free function, so its test asserts three subtractions instead of standing up an RPC client three times; and the admin tests use `#[tokio::test]` and the crate's HTTP helpers rather than a hand-rolled runtime driver and a second blocking client. Skipped, with reasons: caching `AdmissionMetrics` handles (measured at 143 ns on a path that does a network fetch and an EVM replay, and it would introduce a second handle-construction pattern into a file that consistently uses one); threading the method label down from the batch layer (measured cheaper to recompute at 1 ns than to carry through request extensions); moving the metrics exporter onto the admin runtime (a real gap — it is starved by the same inline tracing the admin listener was isolated from — but a behaviour change to a pre-existing subsystem, so it belongs in its own change); and extracting a `request_shape` module (the wrong-way dependency it targets is already gone). Co-Authored-By: Claude Opus 5 (1M context) --- bin/debug-trace-server/src/admin.rs | 206 ++++++------ bin/debug-trace-server/src/admission.rs | 312 +++++++++++-------- bin/debug-trace-server/src/data_provider.rs | 69 ++-- bin/debug-trace-server/src/main.rs | 85 ++--- bin/debug-trace-server/src/metrics.rs | 60 ++-- bin/debug-trace-server/src/response_cache.rs | 23 +- bin/debug-trace-server/src/rpc_middleware.rs | 46 +-- bin/debug-trace-server/src/rpc_service.rs | 121 +++---- 8 files changed, 507 insertions(+), 415 deletions(-) diff --git a/bin/debug-trace-server/src/admin.rs b/bin/debug-trace-server/src/admin.rs index 30db915f..950ac8c6 100644 --- a/bin/debug-trace-server/src/admin.rs +++ b/bin/debug-trace-server/src/admin.rs @@ -28,16 +28,18 @@ use eyre::{Result, eyre}; use jsonrpsee::{ core::RpcResult, proc_macros::rpc, - server::{Server, ServerConfig}, - types::{ErrorObjectOwned, error::INVALID_PARAMS_CODE}, + server::{Server, ServerConfig, ServerHandle}, }; -use serde::{Deserialize, Serialize}; +use serde::Serialize; use tracing::{info, warn}; -use crate::admission::AdmissionLimiter; +use crate::{ + admission::{AdmissionLimiter, Limit, check_capacity_covers_batch}, + rpc_service::invalid_params_err, +}; /// A snapshot of the gate: what it is enforcing, and what it currently holds. -#[derive(Debug, Clone, Serialize, Deserialize)] +#[derive(Debug, Clone, Serialize)] #[serde(rename_all = "camelCase")] pub struct ConcurrencyLimitInfo { /// Requests admitted but not yet holding an execution permit. @@ -94,10 +96,6 @@ impl AdminApi { } } -fn invalid_params(message: impl Into) -> ErrorObjectOwned { - ErrorObjectOwned::owned(INVALID_PARAMS_CODE, message.into(), None::<()>) -} - #[jsonrpsee::core::async_trait] impl AdminRpcServer for AdminApi { async fn get_concurrency_limit(&self) -> RpcResult { @@ -114,29 +112,28 @@ impl AdminRpcServer for AdminApi { // left running to release one. Refused rather than clamped: silently substituting a // different limit than the one asked for is worse than saying no. if max_concurrent == Some(0) { - return Err(invalid_params( + return Err(invalid_params_err( "maxConcurrent must be at least 1: zero would park every request with nothing \ running to release a permit", )); } if heavy_max_concurrent == Some(0) { - return Err(invalid_params( + return Err(invalid_params_err( "heavyMaxConcurrent must be at least 1: zero would park every heavy-tracer \ request with nothing running to release a permit", )); } - let resulting_concurrent = max_concurrent.unwrap_or_else(|| self.limiter.max_concurrent()); - let resulting_queue = max_queue_size.unwrap_or_else(|| self.limiter.max_queue()); - let resulting_capacity = resulting_concurrent.saturating_add(resulting_queue); - if resulting_capacity < self.batch_item_concurrency { - return Err(invalid_params(format!( - "maxConcurrent ({resulting_concurrent}) + maxQueueSize ({resulting_queue}) must \ - be at least the batch item concurrency ({}): one batch's entries admit \ - independently, so a smaller gate sheds part of every batch even on an idle \ - server", - self.batch_item_concurrency - ))); - } + // The same rule startup enforces, in this caller's vocabulary — see + // `admission::check_capacity_covers_batch`. + check_capacity_covers_batch( + Limit::new( + "maxConcurrent", + max_concurrent.unwrap_or_else(|| self.limiter.max_concurrent()), + ), + Limit::new("maxQueueSize", max_queue_size.unwrap_or_else(|| self.limiter.max_queue())), + Limit::new("the batch item concurrency", self.batch_item_concurrency), + ) + .map_err(invalid_params_err)?; let before = self.snapshot(); if let Some(permits) = max_concurrent { @@ -178,40 +175,17 @@ pub(crate) fn spawn( let (tx, rx) = std::sync::mpsc::channel(); thread::Builder::new() .name("dts-admin".to_owned()) - .spawn(move || { - let runtime = match tokio::runtime::Builder::new_current_thread().enable_all().build() { - Ok(runtime) => runtime, - Err(e) => { - let _ = tx.send(Err(eyre!("failed to build the admin runtime: {e}"))); - return; - } - }; - runtime.block_on(async move { - // A handful of connections is all an operator or a probe needs, and this port - // is unauthenticated. - let config = ServerConfig::builder().max_connections(8).build(); - let server = match Server::builder().set_config(config).build(addr).await { - Ok(server) => server, - Err(e) => { - let _ = tx.send(Err(eyre!("failed to bind --admin-addr ({addr}): {e}"))); - return; - } - }; - let bound = match server.local_addr() { - Ok(bound) => bound, - Err(e) => { - let _ = tx.send(Err(eyre!("admin listener has no local address: {e}"))); - return; - } - }; - let api = AdminApi { limiter, batch_item_concurrency }; - let handle = server.start(api.into_rpc()); + .spawn(move || match bind(addr, limiter, batch_item_concurrency) { + Ok((runtime, bound, handle)) => { if tx.send(Ok(bound)).is_err() { warn!("admin listener started but its caller is gone; shutting it down"); return; } - handle.stopped().await; - }); + runtime.block_on(handle.stopped()); + } + Err(e) => { + let _ = tx.send(Err(e)); + } }) .map_err(|e| eyre!("failed to spawn the admin listener thread: {e}"))?; @@ -221,9 +195,41 @@ pub(crate) fn spawn( Ok(bound) } +/// Builds the admin runtime and starts the listener on it, returning both so the caller's +/// thread can own them for the process's lifetime. +/// +/// Split out so every failure funnels through one `?` chain instead of three hand-written +/// send-and-return arms, each of which had to remember to do both. +fn bind( + addr: SocketAddr, + limiter: Arc, + batch_item_concurrency: u64, +) -> Result<(tokio::runtime::Runtime, SocketAddr, ServerHandle)> { + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .map_err(|e| eyre!("failed to build the admin runtime: {e}"))?; + let (bound, handle) = runtime.block_on(async { + // A handful of connections is all an operator or a probe needs, and this port is + // unauthenticated. + let config = ServerConfig::builder().max_connections(8).build(); + let server = Server::builder() + .set_config(config) + .build(addr) + .await + .map_err(|e| eyre!("failed to bind --admin-addr ({addr}): {e}"))?; + let bound = + server.local_addr().map_err(|e| eyre!("admin listener has no local address: {e}"))?; + let api = AdminApi { limiter, batch_item_concurrency }; + Ok::<_, eyre::Report>((bound, server.start(api.into_rpc()))) + })?; + Ok((runtime, bound, handle)) +} + #[cfg(test)] mod tests { use super::*; + use crate::{response_cache::TraceWeight, rpc_middleware::test_support::post_raw}; const BATCH_ITEM_CONCURRENCY: u64 = 16; @@ -234,14 +240,10 @@ mod tests { } } - fn block_on(f: F) -> F::Output { - tokio::runtime::Builder::new_current_thread().enable_all().build().unwrap().block_on(f) - } - - #[test] - fn get_reports_limits_and_occupancy() { + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn get_reports_limits_and_occupancy() { let api = api(4, 32, 2); - let info = block_on(api.get_concurrency_limit()).expect("get"); + let info = api.get_concurrency_limit().await.expect("get"); assert_eq!(info.max_concurrent, 4); assert_eq!(info.max_queue_size, 32); assert_eq!(info.heavy_max_concurrent, 2); @@ -249,10 +251,10 @@ mod tests { assert_eq!(info.executing_requests, 0); } - #[test] - fn set_applies_only_the_fields_given() { + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn set_applies_only_the_fields_given() { let api = api(4, 32, 2); - let info = block_on(api.set_concurrency_limit(Some(9), None, None)).expect("set"); + let info = api.set_concurrency_limit(Some(9), None, None).await.expect("set"); assert_eq!(info.max_concurrent, 9); assert_eq!(info.max_queue_size, 32, "an omitted field is left alone"); assert_eq!(info.heavy_max_concurrent, 2); @@ -262,13 +264,15 @@ mod tests { /// Zero execution permits would park every subsequent request with nothing left running /// to release one — a state only a restart recovers from. Refused rather than clamped: /// quietly enforcing a different limit than the one asked for is its own failure. - #[test] - fn set_rejects_zero_permits() { + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn set_rejects_zero_permits() { let api = api(4, 32, 2); for (concurrent, heavy) in [(Some(0), None), (None, Some(0))] { - let err = block_on(api.set_concurrency_limit(concurrent, None, heavy)) + let err = api + .set_concurrency_limit(concurrent, None, heavy) + .await .expect_err("zero permits must be refused"); - assert_eq!(err.code(), INVALID_PARAMS_CODE); + assert_eq!(err.code(), jsonrpsee::types::error::INVALID_PARAMS_CODE); } assert_eq!(api.limiter.max_concurrent(), 4, "a refused write changes nothing"); assert_eq!(api.limiter.heavy_max_concurrent(), 2); @@ -276,65 +280,61 @@ mod tests { /// The same rule startup enforces: a gate narrower than one batch's concurrent entries /// sheds part of every batch even on an idle server, so the setter refuses to create it. - #[test] - fn set_rejects_a_gate_narrower_than_one_batch() { + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn set_rejects_a_gate_narrower_than_one_batch() { let api = api(4, 32, 2); - let err = block_on(api.set_concurrency_limit(Some(1), Some(1), None)) + let err = api + .set_concurrency_limit(Some(1), Some(1), None) + .await .expect_err("2 total is below the batch item concurrency"); - assert_eq!(err.code(), INVALID_PARAMS_CODE); + assert_eq!(err.code(), jsonrpsee::types::error::INVALID_PARAMS_CODE); assert_eq!(api.limiter.max_concurrent(), 4); assert_eq!(api.limiter.max_queue(), 32); - block_on(api.set_concurrency_limit(Some(1), Some(BATCH_ITEM_CONCURRENCY - 1), None)) + api.set_concurrency_limit(Some(1), Some(BATCH_ITEM_CONCURRENCY - 1), None) + .await .expect("exactly at the floor is allowed"); } /// Lowering a limit below current occupancy must not abort anything — it stops admitting /// until the excess drains. The opposite would make a routine retune a client-visible /// incident. - #[test] - fn lowering_a_limit_does_not_abort_in_flight_work() { + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn lowering_a_limit_does_not_abort_in_flight_work() { let api = api(4, 32, 2); - block_on(async { - let cutoff = std::time::Instant::now() + std::time::Duration::from_secs(30); - let held = api - .limiter - .acquire_execution(crate::metrics::METHOD_TRACE_BLOCK, false, cutoff) - .await - .expect("permit"); - api.set_concurrency_limit(Some(1), None, None).await.expect("set"); - assert_eq!(api.limiter.executing(), 1, "the in-flight request kept its permit"); - drop(held); - }); + let cutoff = std::time::Instant::now() + std::time::Duration::from_secs(30); + let held = api + .limiter + .acquire_execution(crate::metrics::METHOD_TRACE_BLOCK, TraceWeight::Normal, cutoff) + .await + .expect("permit"); + api.set_concurrency_limit(Some(1), None, None).await.expect("set"); + assert_eq!(api.limiter.executing(), 1, "the in-flight request kept its permit"); + drop(held); } /// The listener binds, serves the namespace, and a write over the wire reaches the /// limiter the request path reads. - #[test] - fn admin_listener_binds_and_serves() { + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn admin_listener_binds_and_serves() { let limiter = AdmissionLimiter::new(4, 32, 2); let addr = spawn("127.0.0.1:0".parse().unwrap(), Arc::clone(&limiter), 16) .expect("the admin listener binds"); - let post = |body: &str| { - reqwest::blocking::Client::new() - .post(format!("http://{addr}")) - .header("content-type", "application/json") - .body(body.to_owned()) - .send() - .unwrap() - .json::() - .unwrap() - }; - - let got = - post(r#"{"jsonrpc":"2.0","id":1,"method":"admin_getConcurrencyLimit","params":[]}"#); + let got = post_raw( + addr, + r#"{"jsonrpc":"2.0","id":1,"method":"admin_getConcurrencyLimit","params":[]}"#.into(), + ) + .await; assert_eq!(got["result"]["maxConcurrent"], serde_json::json!(4)); assert_eq!(got["result"]["maxQueueSize"], serde_json::json!(32)); - let set = post( - r#"{"jsonrpc":"2.0","id":2,"method":"admin_setConcurrencyLimit","params":[64,128,3]}"#, - ); + let set = post_raw( + addr, + r#"{"jsonrpc":"2.0","id":2,"method":"admin_setConcurrencyLimit","params":[64,128,3]}"# + .into(), + ) + .await; assert_eq!(set["result"]["maxConcurrent"], serde_json::json!(64)); assert_eq!(limiter.max_concurrent(), 64, "the wire write reached the live limiter"); assert_eq!(limiter.max_queue(), 128); diff --git a/bin/debug-trace-server/src/admission.rs b/bin/debug-trace-server/src/admission.rs index 9e10b34c..5732d08d 100644 --- a/bin/debug-trace-server/src/admission.rs +++ b/bin/debug-trace-server/src/admission.rs @@ -62,7 +62,10 @@ use jsonrpsee::server::middleware::rpc::{ use tokio::sync::{OwnedSemaphorePermit, Semaphore}; use tower::Layer; -use crate::metrics::{self, AdmissionMetrics}; +use crate::{ + metrics::{self, AdmissionMetrics}, + response_cache::TraceWeight, +}; /// JSON-RPC error code for a request turned away by the gate. /// @@ -74,9 +77,12 @@ pub(crate) const QUEUE_FULL_CODE: i32 = -32013; /// The message paired with [`QUEUE_FULL_CODE`], byte-identical to mega-reth's. pub(crate) const QUEUE_FULL_MESSAGE: &str = "Request queue is full"; -/// Builds the shed error response body. -fn queue_full_error() -> jsonrpsee::types::ErrorObjectOwned { - jsonrpsee::types::ErrorObjectOwned::owned(QUEUE_FULL_CODE, QUEUE_FULL_MESSAGE, None::<()>) +/// Builds the shed error response body — the single construction site for the shed contract. +/// +/// `borrowed` rather than `owned`: the message is a `&'static str`, so this allocates nothing +/// on the one path that by definition runs while the process is already under strain. +pub(crate) fn queue_full_error() -> jsonrpsee::types::ErrorObjectOwned { + jsonrpsee::types::ErrorObject::borrowed(QUEUE_FULL_CODE, QUEUE_FULL_MESSAGE, None) } /// A permit count that can be raised and lowered while requests are in flight, without @@ -188,6 +194,76 @@ impl ResizableSemaphore { fn checked_out(&self) -> usize { self.checked_out.load(Ordering::Relaxed) } + + /// Acquires one permit, giving up at `cutoff`. + async fn acquire(self: &Arc, cutoff: Instant) -> Result { + let sem = Arc::clone(&self.sem); + let permit = tokio::time::timeout_at(cutoff.into(), sem.acquire_owned()) + .await + .map_err(|_| AdmissionError::Overloaded)? + // The semaphore is never closed for the process's lifetime. + .map_err(|_| AdmissionError::Overloaded)?; + self.checked_out.fetch_add(1, Ordering::Acquire); + Ok(DebtAwarePermit { permit: Some(permit), owner: Arc::clone(self) }) + } +} + +/// How a caller spells a limit, so a shared rule can name it in the caller's own vocabulary — +/// CLI flags at startup, JSON fields over the admin RPC. The same shape as +/// `stateless_common::R2Flag`, and for the same reason: the rule and its rationale exist once +/// while each entry point still produces an error its own audience recognizes. +pub(crate) struct Limit<'a> { + pub(crate) name: &'a str, + pub(crate) value: u64, +} + +impl<'a> Limit<'a> { + pub(crate) fn new(name: &'a str, value: u64) -> Self { + Self { name, value } + } +} + +/// Rejects a gate too narrow to admit one batch's worth of concurrent entries. +/// +/// A batch's entries admit independently, so a total below `--batch-item-concurrency` sheds +/// part of every batch on a completely idle server. Enforced identically at startup and on the +/// admin RPC, because a rule written twice is a rule that drifts. +pub(crate) fn check_capacity_covers_batch( + concurrent: Limit<'_>, + queue: Limit<'_>, + batch: Limit<'_>, +) -> Result<(), String> { + if concurrent.value.saturating_add(queue.value) >= batch.value { + return Ok(()); + } + Err(format!( + "{} ({}) + {} ({}) must be at least {} ({}): one batch's entries admit independently, \ + so a smaller gate sheds part of every batch even on an idle server", + concurrent.name, concurrent.value, queue.name, queue.value, batch.name, batch.value + )) +} + +/// Claims one unit of a bounded counter, or reports that the bound is already reached. +/// +/// The lock-free half of admission, shared by the process-wide gate and the heavy-class gate: +/// the subtle part is the pair of orderings (`Acquire` on the claim, `Release` in the guard +/// that releases it), and a second copy would let those drift with nothing to catch it. +fn try_claim(counter: &AtomicUsize, capacity: u64) -> bool { + let mut current = counter.load(Ordering::Relaxed); + loop { + if current as u64 >= capacity { + return false; + } + match counter.compare_exchange_weak( + current, + current + 1, + Ordering::Acquire, + Ordering::Relaxed, + ) { + Ok(_) => return true, + Err(actual) => current = actual, + } + } } /// Tokio panics past this, and the admin RPC takes operator input. @@ -213,29 +289,6 @@ impl Drop for DebtAwarePermit { } } -/// How much of the process's memory budget a request's tracer is expected to want. -/// -/// The distinction exists because one execution budget cannot serve both: sized for the -/// `callTracer` traffic that has been measured clean it admits hundreds of concurrent -/// blocks, and hundreds of concurrent `prestateTracer` traces over large blocks is the -/// shape that has already OOM-killed this server once. [`TraceWeight::Heavy`] requests pass -/// a second, much smaller budget first, so the worst-case resident set is a number an -/// operator can compute rather than a property of what clients happen to ask for. -#[derive(Debug, Clone, Copy, PartialEq, Eq)] -pub(crate) enum TraceWeight { - /// Bounded output per transaction; the request's cost is dominated by the fetch. - Normal, - /// Output can run to hundreds of megabytes on a large block. - Heavy, -} - -impl TraceWeight { - /// Whether this request must pass the heavy sub-cap. - pub(crate) fn is_heavy(self) -> bool { - matches!(self, Self::Heavy) - } -} - /// Why a request could not obtain an execution permit. #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub(crate) enum AdmissionError { @@ -356,26 +409,11 @@ impl AdmissionLimiter { /// `None` means shed. This is the "can this request be served at all" question answered /// before any parsing, fetching or tracing happens. fn try_admit(self: &Arc, method: &'static str) -> Option { - let capacity = self.capacity(); - let mut current = self.in_flight.load(Ordering::Relaxed); - loop { - if current as u64 >= capacity { - return None; - } - match self.in_flight.compare_exchange_weak( - current, - current + 1, - Ordering::Acquire, - Ordering::Relaxed, - ) { - Ok(_) => { - let gauges = AdmissionMetrics::new_for_method(method); - gauges.in_flight_delta(1.0); - return Some(InFlightGuard { limiter: Arc::clone(self), gauges }); - } - Err(actual) => current = actual, - } - } + try_claim(&self.in_flight, self.capacity()).then(|| { + let gauges = AdmissionMetrics::new_for_method(method); + gauges.in_flight_delta(1.0); + InFlightGuard { limiter: Arc::clone(self), gauges } + }) } /// Waits for the permits this request needs to fetch and replay a block. @@ -393,18 +431,18 @@ impl AdmissionLimiter { pub(crate) async fn acquire_execution( self: &Arc, method: &'static str, - heavy: bool, + weight: TraceWeight, cutoff: Instant, ) -> Result { let started = Instant::now(); - let heavy_permit = if heavy { + let heavy_permit = if weight == TraceWeight::Heavy { let _slot = self.enter_heavy()?; - let permit = HeavyPermit::new(acquire_by(&self.heavy, cutoff).await?); + let permit = HeavyPermit::new(self.heavy.acquire(cutoff).await?); Some((permit, _slot)) } else { None }; - let permit = acquire_by(&self.execution, cutoff).await?; + let permit = self.execution.acquire(cutoff).await?; metrics::record_admission_permit_wait(started.elapsed().as_secs_f64()); let gauges = AdmissionMetrics::new_for_method(method); @@ -414,40 +452,12 @@ impl AdmissionLimiter { /// Claims one of the heavy class's slots, or refuses when it already holds its share. fn enter_heavy(self: &Arc) -> Result { - let capacity = self.heavy_capacity(); - let mut current = self.heavy_in_flight.load(Ordering::Relaxed); - loop { - if current as u64 >= capacity { - return Err(AdmissionError::Overloaded); - } - match self.heavy_in_flight.compare_exchange_weak( - current, - current + 1, - Ordering::Acquire, - Ordering::Relaxed, - ) { - Ok(_) => return Ok(HeavySlot { limiter: Arc::clone(self) }), - Err(actual) => current = actual, - } - } + try_claim(&self.heavy_in_flight, self.heavy_capacity()) + .then(|| HeavySlot { limiter: Arc::clone(self) }) + .ok_or(AdmissionError::Overloaded) } } -/// Acquires one permit, giving up at `cutoff`. -async fn acquire_by( - semaphore: &Arc, - cutoff: Instant, -) -> Result { - let sem = Arc::clone(&semaphore.sem); - let permit = tokio::time::timeout_at(cutoff.into(), sem.acquire_owned()) - .await - .map_err(|_| AdmissionError::Overloaded)? - // The semaphore is never closed for the process's lifetime. - .map_err(|_| AdmissionError::Overloaded)?; - semaphore.checked_out.fetch_add(1, Ordering::Acquire); - Ok(DebtAwarePermit { permit: Some(permit), owner: Arc::clone(semaphore) }) -} - /// Holds one of the heavy class's share of the admitted budget. pub(crate) struct HeavySlot { limiter: Arc, @@ -607,10 +617,24 @@ mod tests { const METHOD: &str = METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER; /// A cutoff far enough away that a test never trips the deadline clamp by accident. - fn far() -> Instant { + pub(crate) fn far() -> Instant { Instant::now() + Duration::from_secs(30) } + /// Takes `n` ordinary execution permits and hands them back for the caller to hold. + async fn hold(limiter: &Arc, n: usize) -> Vec { + let mut held = Vec::with_capacity(n); + for _ in 0..n { + held.push( + limiter + .acquire_execution(METHOD, TraceWeight::Normal, far()) + .await + .expect("permit"), + ); + } + held + } + #[test] fn admits_exactly_queue_plus_concurrent() { let limiter = AdmissionLimiter::new(2, 3, 1); @@ -633,8 +657,8 @@ mod tests { assert!(limiter.try_admit(METHOD).is_some()); } - #[tokio::test(flavor = "multi_thread", worker_threads = 2)] - async fn queue_is_zero_means_execute_or_shed() { + #[test] + fn queue_is_zero_means_execute_or_shed() { let limiter = AdmissionLimiter::new(1, 0, 1); let _first = limiter.try_admit(METHOD).expect("the one execution slot is admissible"); assert!(limiter.try_admit(METHOD).is_none(), "with no queue there is nowhere to wait"); @@ -643,18 +667,22 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn heavy_requests_pass_both_budgets() { let limiter = AdmissionLimiter::new(8, 8, 1); - let heavy = limiter.acquire_execution(METHOD, true, far()).await.expect("first heavy"); + let heavy = limiter + .acquire_execution(METHOD, TraceWeight::Heavy, far()) + .await + .expect("first heavy"); assert_eq!(limiter.executing(), 1); // The sub-cap is full, so a second heavy request waits even though seven ordinary // execution permits are free. - let blocked = limiter.acquire_execution(METHOD, true, Instant::now()).await; + let blocked = limiter.acquire_execution(METHOD, TraceWeight::Heavy, Instant::now()).await; assert_eq!(blocked.unwrap_err(), AdmissionError::Overloaded); // An ordinary request is unaffected by the heavy sub-cap. - let _normal = limiter.acquire_execution(METHOD, false, far()).await.expect("normal"); + let _normal = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("normal"); drop(heavy); - limiter.acquire_execution(METHOD, true, far()).await.expect("sub-cap freed"); + limiter.acquire_execution(METHOD, TraceWeight::Heavy, far()).await.expect("sub-cap freed"); } /// A request that queued past the point where its remaining budget could still cover the @@ -663,11 +691,16 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn permit_wait_gives_up_at_the_cutoff() { let limiter = AdmissionLimiter::new(1, 8, 1); - let _held = limiter.acquire_execution(METHOD, false, far()).await.expect("first"); + let _held = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("first"); let started = Instant::now(); let refused = limiter - .acquire_execution(METHOD, false, Instant::now() + Duration::from_millis(50)) + .acquire_execution( + METHOD, + TraceWeight::Normal, + Instant::now() + Duration::from_millis(50), + ) .await; assert_eq!(refused.unwrap_err(), AdmissionError::Overloaded); assert!(started.elapsed() < Duration::from_secs(5), "it gave up, it did not hang"); @@ -686,8 +719,10 @@ mod tests { let limiter = Arc::clone(&limiter); tasks.spawn(async move { for _ in 0..250 { - let permit = - limiter.acquire_execution(METHOD, false, far()).await.expect("permit"); + let permit = limiter + .acquire_execution(METHOD, TraceWeight::Normal, far()) + .await + .expect("permit"); drop(permit); tokio::task::yield_now().await; } @@ -709,12 +744,15 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn raising_the_limit_wakes_parked_waiters() { let limiter = AdmissionLimiter::new(1, 64, 1); - let _held = limiter.acquire_execution(METHOD, false, far()).await.expect("first"); + let _held = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("first"); let mut waiters = tokio::task::JoinSet::new(); for _ in 0..4 { let limiter = Arc::clone(&limiter); - waiters.spawn(async move { limiter.acquire_execution(METHOD, false, far()).await }); + waiters.spawn(async move { + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await + }); } // Let them all reach the wait before the capacity appears. tokio::time::sleep(Duration::from_millis(50)).await; @@ -739,13 +777,7 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn shrinking_below_checked_out_permits_settles_on_release() { let limiter = AdmissionLimiter::new(4, 64, 1); - let held: Vec<_> = { - let mut held = Vec::new(); - for _ in 0..4 { - held.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); - } - held - }; + let held = hold(&limiter, 4).await; assert_eq!(limiter.executing(), 4); limiter.set_max_concurrent(1); @@ -753,9 +785,16 @@ mod tests { // Releasing three must not make three permits available again: they pay off the debt. drop(held); - let _one = limiter.acquire_execution(METHOD, false, far()).await.expect("the one permit"); + let _one = limiter + .acquire_execution(METHOD, TraceWeight::Normal, far()) + .await + .expect("the one permit"); let second = limiter - .acquire_execution(METHOD, false, Instant::now() + Duration::from_millis(50)) + .acquire_execution( + METHOD, + TraceWeight::Normal, + Instant::now() + Duration::from_millis(50), + ) .await; assert_eq!( second.unwrap_err(), @@ -783,7 +822,9 @@ mod tests { for _ in 0..12 { admitted.push(limiter.try_admit(METHOD).expect("admitted by the class-blind gate")); let limiter = Arc::clone(&limiter); - waiters.spawn(async move { limiter.acquire_execution(METHOD, true, far()).await }); + waiters.spawn(async move { + limiter.acquire_execution(METHOD, TraceWeight::Heavy, far()).await + }); } tokio::time::sleep(Duration::from_millis(100)).await; @@ -795,7 +836,7 @@ mod tests { // Which is the point: an ordinary request still gets a permit, because the execution // permits the heavy flood was not using are still reachable. let ordinary = limiter - .acquire_execution(METHOD, false, far()) + .acquire_execution(METHOD, TraceWeight::Normal, far()) .await .expect("ordinary traffic is not starved by a heavy flood"); drop(ordinary); @@ -808,10 +849,16 @@ mod tests { let limiter = AdmissionLimiter::new(8, 0, 2); assert_eq!(limiter.heavy_capacity(), 2, "no queue means no heavy waiters either"); - let _first = limiter.acquire_execution(METHOD, true, far()).await.expect("first heavy"); - let _second = limiter.acquire_execution(METHOD, true, far()).await.expect("second heavy"); + let _first = limiter + .acquire_execution(METHOD, TraceWeight::Heavy, far()) + .await + .expect("first heavy"); + let _second = limiter + .acquire_execution(METHOD, TraceWeight::Heavy, far()) + .await + .expect("second heavy"); let started = Instant::now(); - let refused = limiter.acquire_execution(METHOD, true, far()).await; + let refused = limiter.acquire_execution(METHOD, TraceWeight::Heavy, far()).await; assert_eq!(refused.unwrap_err(), AdmissionError::Overloaded); // Promptness is the assertion that discriminates: sharing the class-blind budget also // ends in `Overloaded`, but only after parking on the sub-cap until the cutoff — which @@ -828,11 +875,14 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn heavy_occupancy_is_visible_while_waiting_for_an_execution_permit() { let limiter = AdmissionLimiter::new(1, 8, 1); - let _blocker = limiter.acquire_execution(METHOD, false, far()).await.expect("blocker"); + let _blocker = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("blocker"); let waiting = { let limiter = Arc::clone(&limiter); - tokio::spawn(async move { limiter.acquire_execution(METHOD, true, far()).await }) + tokio::spawn(async move { + limiter.acquire_execution(METHOD, TraceWeight::Heavy, far()).await + }) }; tokio::time::sleep(Duration::from_millis(100)).await; @@ -860,7 +910,9 @@ mod tests { let limiter = Arc::clone(&limiter); tasks.spawn(async move { for _ in 0..200 { - if let Ok(permit) = limiter.acquire_execution(METHOD, false, far()).await { + if let Ok(permit) = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await + { tokio::task::yield_now().await; drop(permit); } @@ -911,12 +963,8 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn occupancy_stays_truthful_while_a_shrink_is_outstanding() { let limiter = AdmissionLimiter::new(4, 64, 4); - let mut admitted = Vec::new(); - let mut held = Vec::new(); - for _ in 0..4 { - admitted.push(limiter.try_admit(METHOD).expect("admit")); - held.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); - } + let _admitted: Vec<_> = (0..4).map(|_| limiter.try_admit(METHOD).expect("admit")).collect(); + let mut held = hold(&limiter, 4).await; assert_eq!(limiter.executing(), 4); limiter.set_max_concurrent(1); @@ -935,8 +983,10 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn heavy_occupancy_is_reported_separately() { let limiter = AdmissionLimiter::new(8, 8, 2); - let _heavy = limiter.acquire_execution(METHOD, true, far()).await.expect("heavy"); - let _normal = limiter.acquire_execution(METHOD, false, far()).await.expect("normal"); + let _heavy = + limiter.acquire_execution(METHOD, TraceWeight::Heavy, far()).await.expect("heavy"); + let _normal = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("normal"); assert_eq!(limiter.executing(), 2, "both hold an ordinary execution permit"); assert_eq!(limiter.heavy_executing(), 1, "only one holds a heavy permit"); } @@ -946,10 +996,15 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn a_heavy_request_that_times_out_releases_its_sub_cap_permit() { let limiter = AdmissionLimiter::new(1, 8, 1); - let _blocker = limiter.acquire_execution(METHOD, false, far()).await.expect("blocker"); + let _blocker = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("blocker"); let refused = limiter - .acquire_execution(METHOD, true, Instant::now() + Duration::from_millis(50)) + .acquire_execution( + METHOD, + TraceWeight::Heavy, + Instant::now() + Duration::from_millis(50), + ) .await; assert_eq!(refused.unwrap_err(), AdmissionError::Overloaded); assert_eq!( @@ -964,18 +1019,12 @@ mod tests { #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn growing_cancels_outstanding_debt_first() { let limiter = AdmissionLimiter::new(4, 64, 1); - let mut held = Vec::new(); - for _ in 0..4 { - held.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); - } + let held = hold(&limiter, 4).await; limiter.set_max_concurrent(1); // 4 checked out, 3 of debt limiter.set_max_concurrent(4); // back where we started; debt must simply vanish drop(held); - let mut regained = Vec::new(); - for _ in 0..4 { - regained.push(limiter.acquire_execution(METHOD, false, far()).await.expect("permit")); - } + let _regained = hold(&limiter, 4).await; assert_eq!(limiter.executing(), 4, "all four permits came back, none forgotten twice"); } @@ -985,7 +1034,8 @@ mod tests { let _admitted: Vec<_> = (0..3).map(|_| limiter.try_admit(METHOD).expect("admit")).collect(); assert_eq!(limiter.queued(), 3, "admitted, none executing yet"); - let _permit = limiter.acquire_execution(METHOD, false, far()).await.expect("permit"); + let _permit = + limiter.acquire_execution(METHOD, TraceWeight::Normal, far()).await.expect("permit"); assert_eq!(limiter.executing(), 1); assert_eq!(limiter.queued(), 2); } diff --git a/bin/debug-trace-server/src/data_provider.rs b/bin/debug-trace-server/src/data_provider.rs index 425d12e1..7e8b03c0 100644 --- a/bin/debug-trace-server/src/data_provider.rs +++ b/bin/debug-trace-server/src/data_provider.rs @@ -95,6 +95,15 @@ impl WitnessFetchConfig { } } +/// The share of a request's budget held back from the admission queue for the work itself. +/// +/// A free function rather than a method: it is two `Duration`s in and one out, and reaching it +/// through a `DataProvider` would make its tests stand up an RPC client and four caches to +/// assert a subtraction. +fn permit_reserve(witness_timeout: Duration, block_fetch_timeout: Duration) -> Duration { + if witness_timeout < block_fetch_timeout { witness_timeout } else { block_fetch_timeout / 2 } +} + /// Block data bundle containing all information needed for stateless execution. /// /// This struct aggregates the block, its witness (state proof), and all @@ -561,8 +570,7 @@ impl DataProvider { /// The share of a request's budget held back from the admission queue for the work itself. fn permit_reserve(&self) -> Duration { - let witness = self.witness_cfg.witness_timeout; - if witness < self.block_fetch_timeout { witness } else { self.block_fetch_timeout / 2 } + permit_reserve(self.witness_cfg.witness_timeout, self.block_fetch_timeout) } /// The longest a request may wait for an execution permit under the configured budgets — @@ -1865,40 +1873,33 @@ mod tests { /// pointing an operator at client load rather than at their own timeout setting. #[test] fn permit_reserve_never_swallows_the_whole_budget() { - let reserve = |witness_secs: u64, fetch_secs: u64| { - let provider = DataProvider::new( - Arc::new( - RpcClient::new_with_config( - &["http://127.0.0.1:1"], - &["http://127.0.0.1:1"], - RpcClientConfig::trace_server(), - None, - ) - .unwrap(), - ), - None, - None, - test_support::noop_contract_cache(), - WitnessFetchConfig::with_defaults(witness_secs), - Duration::from_secs(fetch_secs), - 1024, + let secs = Duration::from_secs; + for (witness, block_fetch, expected_reserve, note) in [ + (8u64, 13u64, secs(8), "the ordinary case: the witness stage keeps its full budget"), + (20, 13, secs(13) / 2, "inverted: capped at half, so the queue keeps the other half"), + (13, 13, secs(13) / 2, "equal budgets are the boundary and must stay usable"), + ] { + let reserve = permit_reserve(secs(witness), secs(block_fetch)); + assert_eq!(reserve, expected_reserve, "{note}"); + assert!( + reserve < secs(block_fetch), + "{note}: a reserve equal to the whole budget would leave a zero-length permit \ + wait, silently reducing --admission-max-queue to a no-op" ); - (provider.max_permit_wait(), provider.permit_cutoff(provider.fetch_deadline())) - }; - - // The ordinary case: the witness stage keeps its full budget, the queue gets the rest. - let (wait, cutoff) = reserve(8, 13); - assert_eq!(wait, Duration::from_secs(5), "13s budget less the 8s witness reserve"); - assert!(cutoff > Instant::now(), "a request may still wait"); - - // The inverted case: the reserve is capped at half, so the queue keeps the other half. - let (wait, cutoff) = reserve(20, 13); - assert_eq!(wait, Duration::from_secs(13) - Duration::from_secs(13) / 2); - assert!(cutoff > Instant::now(), "the queue is still usable, not silently inert"); + } + } - // Equal budgets are the boundary of the old behaviour and must stay usable too. - let (wait, _) = reserve(13, 13); - assert_eq!(wait, Duration::from_secs(13) / 2); + /// The provider hands that same reserve to the cutoff a request actually waits against. + #[test] + fn permit_cutoff_leaves_the_queue_usable() { + let provider = provider_with_tiers( + "http://127.0.0.1:1", + None, + None, + test_support::noop_contract_cache(), + ); + assert!(provider.max_permit_wait() > Duration::ZERO, "the queue is not a no-op"); + assert!(provider.permit_cutoff(provider.fetch_deadline()) > Instant::now()); } /// [`provider_with_tiers`] with no memory cache and an empty noop-backed contract diff --git a/bin/debug-trace-server/src/main.rs b/bin/debug-trace-server/src/main.rs index 824f2f70..c7b8cf86 100644 --- a/bin/debug-trace-server/src/main.rs +++ b/bin/debug-trace-server/src/main.rs @@ -710,18 +710,18 @@ fn validate_args(args: &Args) -> Result { (frontier vs historical) to the local DB tip" ); } - // A batch's entries admit independently, so a gate narrower than one batch's concurrent - // entries would shed part of every batch on a completely idle server. - let admission_capacity = args.admission_max_concurrent.saturating_add(args.admission_max_queue); - if !args.admission_disabled && admission_capacity < u64::from(args.batch_item_concurrency) { - eyre::bail!( - "--admission-max-concurrent ({}) + --admission-max-queue ({}) must be at least \ - --batch-item-concurrency ({}): one batch's entries admit independently, so a \ - smaller gate sheds part of every batch even on an idle server", - args.admission_max_concurrent, - args.admission_max_queue, - args.batch_item_concurrency - ); + // Shared with the admin RPC's setter, so the startup gate and the runtime gate cannot + // enforce different rules. + if !args.admission_disabled { + admission::check_capacity_covers_batch( + admission::Limit::new("--admission-max-concurrent", args.admission_max_concurrent), + admission::Limit::new("--admission-max-queue", args.admission_max_queue), + admission::Limit::new( + "--batch-item-concurrency", + u64::from(args.batch_item_concurrency), + ), + ) + .map_err(|e| eyre::eyre!(e))?; } // The batch builder holds whole entry bodies, so a batch cap below one entry's cap could // never assemble even a single maximal response — and it must clear it by enough for the @@ -1161,22 +1161,18 @@ async fn main() -> Result<()> { // The bound admin address, kept only for the record; the listener itself is owned by its // own thread for the process's lifetime (see `admin::spawn`). - let _admin_addr = match (admin_bind_addr(&args)?, admission) { + match (admin_bind_addr(&args)?, admission) { (Some(admin_addr), Some(limiter)) => { - Some(admin::spawn(admin_addr, limiter, u64::from(args.batch_item_concurrency))?) + admin::spawn(admin_addr, limiter, u64::from(args.batch_item_concurrency))?; } (Some(_), None) => { warn!("--admin-addr is set but --admission-disabled: no limits to serve, skipping"); - None - } - (None, _) => { - warn!( - "--admin-addr not set: admission limits are fixed for this process's lifetime \ - and can only be changed by restarting" - ); - None } - }; + (None, _) => warn!( + "--admin-addr not set: admission limits are fixed for this process's lifetime and \ + can only be changed by restarting" + ), + } info!(listen_addr = %addr, "Server started"); handle.stopped().await; @@ -1190,23 +1186,24 @@ async fn main() -> Result<()> { /// the failure mode of an omission here is an unprotected endpoint, discovered under load. /// `debug_getCacheStatus` is the one deliberate exemption; see `metrics::GATED_METHODS`. fn assert_admission_covers_module(module: &jsonrpsee::server::RpcModule<()>) { - if let Some(name) = ungated_method(module.method_names()) { + if let Some(name) = unregistered_method(module.method_names()) { panic!( - "method {name} is registered but neither gated by admission control nor \ - deliberately exempt; add it to metrics::GATED_METHODS or to the exemption list" + "method {name} is registered on the RPC module but absent from \ + metrics::ALL_METHODS, so admission control lets it through ungated and its \ + metrics collapse onto the `unknown` label; add it there" ); } } -/// The first registered method that is neither gated nor deliberately exempt, if any. -fn ungated_method<'a>(names: impl Iterator) -> Option<&'a str> { - // The one endpoint that does no I/O and reports what the server is doing; see - // `metrics::GATED_METHODS` for why it is exempt. - const EXEMPT: &[&str] = - &[metrics::METHOD_DEBUG_GET_CACHE_STATUS, metrics::TIMED_METHOD_DEBUG_GET_CACHE_STATUS]; - names - .filter(|name| !EXEMPT.contains(name)) - .find(|name| !metrics::is_gated(metrics::method_label(name))) +/// The first method registered on the module that `metrics` does not know about, if any. +/// +/// Gating is derived — everything in `metrics::ALL_METHODS` is gated unless it is in +/// `metrics::GATE_EXEMPT_METHODS` — so a registered method can no longer be *accidentally* +/// ungated by omission from a second list. What can still happen is registering a method the +/// metrics registry has never heard of, which both bypasses the gate and collapses its metrics +/// onto `unknown`. That is the one condition worth failing startup over. +fn unregistered_method<'a>(mut names: impl Iterator) -> Option<&'a str> { + names.find(|name| !metrics::is_registered(name)) } /// Initializes the validator database if data_dir is provided. @@ -1710,19 +1707,27 @@ mod tests { /// The admission allowlist is spelled by name, so a method added later would silently /// never be gated — an unprotected endpoint, discovered under load. #[test] - fn every_registered_method_is_gated_or_deliberately_exempt() { - let registered: Vec<&str> = metrics::ALL_METHOD_NAMES + fn every_registered_method_is_known_to_metrics() { + let registered: Vec<&str> = metrics::ALL_METHODS .iter() .copied() .chain(metrics::TIMED_METHOD_ALIASES.iter().map(|(alias, _)| *alias)) .collect(); - assert_eq!(ungated_method(registered.iter().copied()), None); + assert_eq!(unregistered_method(registered.iter().copied()), None); assert_eq!( - ungated_method(["debug_traceBlockByNumber", "debug_newThing"].into_iter()), + unregistered_method(["debug_traceBlockByNumber", "debug_newThing"].into_iter()), Some("debug_newThing"), - "an unrecognized method must be reported, not folded into `unknown` and ignored" + "a method metrics has never heard of must be reported, not silently ungated" ); + + // Gating is derived, so the exemption is spelled once and both spellings resolve alike. + assert!(metrics::is_gated(metrics::METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER)); + for name in + [metrics::METHOD_DEBUG_GET_CACHE_STATUS, metrics::TIMED_METHOD_DEBUG_GET_CACHE_STATUS] + { + assert!(!metrics::is_gated(metrics::method_label(name)), "{name} stays exempt"); + } } #[test] diff --git a/bin/debug-trace-server/src/metrics.rs b/bin/debug-trace-server/src/metrics.rs index 6f68c1c9..fc37ad33 100644 --- a/bin/debug-trace-server/src/metrics.rs +++ b/bin/debug-trace-server/src/metrics.rs @@ -63,11 +63,7 @@ pub const CACHE_TYPE_TRACE: &str = "trace_block"; pub const CACHE_TYPE_BLOCK_DATA: &str = "block_data"; // All known RPC methods (for resolving &str → &'static str) -/// [`ALL_METHODS`] exposed for the admission-coverage test in `main`. -#[cfg(test)] -pub const ALL_METHOD_NAMES: &[&str] = ALL_METHODS; - -const ALL_METHODS: &[&str] = &[ +pub const ALL_METHODS: &[&str] = &[ METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, METHOD_DEBUG_TRACE_BLOCK_BY_HASH, METHOD_DEBUG_TRACE_TRANSACTION, @@ -76,30 +72,29 @@ const ALL_METHODS: &[&str] = &[ METHOD_TRACE_TRANSACTION, ]; -/// The methods the inbound admission gate applies to: everything that fetches a block and -/// runs a tracer, i.e. everything whose cost is a block-unit. +/// Methods the inbound admission gate deliberately lets through. /// -/// `debug_getCacheStatus` is deliberately absent — it is pure atomic reads, touches neither -/// upstream nor EVM, and shedding the one endpoint an operator uses to ask what the server -/// is doing, precisely while it is shedding, would be self-defeating. Unknown methods are -/// absent too: the framework answers them `-32601` in microseconds, so gating buys nothing -/// and would replace that with a misleading `-32013`. +/// `debug_getCacheStatus` is pure atomic reads — it touches neither upstream nor EVM — and +/// shedding the one endpoint an operator uses to ask what the server is doing, precisely while +/// it is shedding, would be self-defeating. /// -/// This is the single source of truth for the allowlist: the admission layer gates exactly -/// these, and [`pre_register_all_metrics`] registers the `shed` arrival series for exactly -/// these. Callers must resolve the wire name through [`method_label`] first, so `timed_` -/// aliases are covered. -pub const GATED_METHODS: &[&str] = &[ - METHOD_DEBUG_TRACE_BLOCK_BY_NUMBER, - METHOD_DEBUG_TRACE_BLOCK_BY_HASH, - METHOD_DEBUG_TRACE_TRANSACTION, - METHOD_TRACE_BLOCK, - METHOD_TRACE_TRANSACTION, -]; +/// This is the only place the exemption is written. Gating is *derived* from it rather than +/// enumerated separately, so a method added to [`ALL_METHODS`] is gated by default and cannot +/// be forgotten; the `timed_` aliases need no entry because [`is_gated`] resolves through +/// [`method_label`] first. +pub const GATE_EXEMPT_METHODS: &[&str] = &[METHOD_DEBUG_GET_CACHE_STATUS]; /// Whether the admission gate applies to an already-resolved method label. +/// +/// Unknown methods are not gated: the framework answers them `-32601` in microseconds, so +/// gating buys nothing and would replace that with a misleading `-32013`. pub fn is_gated(method: &'static str) -> bool { - GATED_METHODS.contains(&method) + ALL_METHODS.contains(&method) && !GATE_EXEMPT_METHODS.contains(&method) +} + +/// The methods the gate applies to — [`ALL_METHODS`] minus [`GATE_EXEMPT_METHODS`]. +pub fn gated_methods() -> impl Iterator { + ALL_METHODS.iter().copied().filter(|m| !GATE_EXEMPT_METHODS.contains(m)) } /// Maps an arbitrary method string onto one of the known `&'static str` labels, so a @@ -107,7 +102,16 @@ pub fn is_gated(method: &'static str) -> bool { /// Unknown methods collapse to `"unknown"`, keeping label cardinality bounded against /// arbitrary client input. pub fn resolve_method(method: &str) -> &'static str { - ALL_METHODS.iter().find(|&&m| m == method).copied().unwrap_or("unknown") + ALL_METHODS.iter().find(|&&m| m == method).copied().unwrap_or(UNKNOWN_METHOD) +} + +/// The label every unregistered method folds onto, bounding cardinality against arbitrary +/// client input. +pub const UNKNOWN_METHOD: &str = "unknown"; + +/// Whether this wire name is one of the methods this server registers (`timed_` alias or not). +pub fn is_registered(method: &str) -> bool { + method_label(method) != UNKNOWN_METHOD } /// RPC method metrics with method label. @@ -948,7 +952,7 @@ fn pre_register_all_metrics() { // Request Layer: admission gate. Occupancy is per gated method; the limit gauges are // global and are re-published on every admin write. - for method in GATED_METHODS.iter().copied() { + for method in gated_methods() { let _ = AdmissionMetrics::new_for_method(method); } let _ = histogram!(ADMISSION_PERMIT_WAIT_SECONDS); @@ -957,7 +961,7 @@ fn pre_register_all_metrics() { // Request Layer: responses discarded for exceeding `--max-response-size`. Every method // that can produce a trace body participates; a nonzero value here is the signal that // clients are asking for more than the process is willing to materialize. - for method in GATED_METHODS.iter().copied() { + for method in gated_methods() { counter!(RESPONSE_OVERSIZED_TOTAL, "method" => method).increment(0); } @@ -1023,7 +1027,7 @@ const BUCKET_SPECS: &[(&str, &[f64])] = &[ ("debug_trace_reorg_depth", REORG_DEPTH_BUCKETS), ("debug_trace_witness_bytes", BYTE_BUCKETS), ("debug_trace_body_cpu_time_seconds", BODY_CPU_TIME_BUCKETS), - ("debug_trace_admission_permit_wait_seconds", ADMISSION_WAIT_BUCKETS), + (ADMISSION_PERMIT_WAIT_SECONDS, ADMISSION_WAIT_BUCKETS), ]; /// Initializes the Prometheus metrics exporter. diff --git a/bin/debug-trace-server/src/response_cache.rs b/bin/debug-trace-server/src/response_cache.rs index 764d9ade..722c8eeb 100644 --- a/bin/debug-trace-server/src/response_cache.rs +++ b/bin/debug-trace-server/src/response_cache.rs @@ -37,7 +37,6 @@ use quick_cache::{Lifecycle, Weighter, sync::Cache}; use tracing::debug; use crate::{ - admission::TraceWeight, metrics::{CACHE_TYPE_DEBUG_TRACE, CACHE_TYPE_TRACE, CacheMetrics, CacheStats}, raw_json::RawJson, }; @@ -166,6 +165,26 @@ impl ResponseVariant { } } +/// How much of the process's memory budget a request's tracer is expected to want. +/// +/// Lives beside [`RequestShape`], which produces it, rather than beside the gate that consumes +/// it: the classification is a property of the request, and the dependency should point from +/// the policy layer to the domain rather than back. +/// +/// The distinction exists because one execution budget cannot serve both: sized for the +/// `callTracer` traffic that has been measured clean it admits hundreds of concurrent blocks, +/// and hundreds of concurrent `prestateTracer` traces over large blocks is the shape that has +/// already OOM-killed this server once. [`TraceWeight::Heavy`] requests pass a second, much +/// smaller budget first, so the worst-case resident set is a number an operator can compute +/// rather than a property of what clients happen to ask for. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum TraceWeight { + /// Bounded output per transaction; the request's cost is dominated by the fetch. + Normal, + /// Output can run to hundreds of megabytes on a large block. + Heavy, +} + /// Classification of a trace request's parameters — the single source of truth shared by /// the cache whitelist, the shape metrics, and malformed-config rejection. #[derive(Debug)] @@ -256,7 +275,6 @@ impl RequestShape { } } - /// Metrics shape label for this request. /// How much memory this request's tracer is expected to want, for the admission gate's /// heavy sub-cap. /// @@ -284,6 +302,7 @@ impl RequestShape { } } + /// Metrics shape label for this request. pub fn label(&self) -> &'static str { match self { Self::Cacheable(variant) => variant.label(), diff --git a/bin/debug-trace-server/src/rpc_middleware.rs b/bin/debug-trace-server/src/rpc_middleware.rs index 0803b730..40a6af85 100644 --- a/bin/debug-trace-server/src/rpc_middleware.rs +++ b/bin/debug-trace-server/src/rpc_middleware.rs @@ -355,6 +355,31 @@ where } } +/// JSON-RPC POST helpers shared by every in-crate test that drives a real server. +#[cfg(test)] +pub(crate) mod test_support { + use std::net::SocketAddr; + + use serde_json::Value; + + pub(crate) async fn post_text(addr: SocketAddr, body: String) -> String { + reqwest::Client::new() + .post(format!("http://{addr}")) + .header("content-type", "application/json") + .body(body) + .send() + .await + .unwrap() + .text() + .await + .unwrap() + } + + pub(crate) async fn post_raw(addr: SocketAddr, body: String) -> Value { + serde_json::from_str(&post_text(addr, body).await).unwrap() + } +} + #[cfg(test)] mod tests { use std::{ @@ -368,7 +393,7 @@ mod tests { }; use serde_json::{Value, json}; - use super::*; + use super::{test_support::*, *}; const SLOW_MS: u64 = 200; const SPIN_MS: u64 = 40; @@ -459,23 +484,6 @@ mod tests { (addr, server.start(test_module())) } - async fn post_text(addr: SocketAddr, body: String) -> String { - reqwest::Client::new() - .post(format!("http://{addr}")) - .header("content-type", "application/json") - .body(body) - .send() - .await - .unwrap() - .text() - .await - .unwrap() - } - - async fn post_raw(addr: SocketAddr, body: String) -> Value { - serde_json::from_str(&post_text(addr, body).await).unwrap() - } - /// The cancel guard counts a drop as a cancellation only while armed — not after /// `settle`, and not once the batch flagged a server-side abort. #[test] @@ -795,7 +803,7 @@ mod tests { let _held = limiter .acquire_execution( crate::metrics::METHOD_TRACE_BLOCK, - false, + crate::response_cache::TraceWeight::Normal, Instant::now() + Duration::from_secs(30), ) .await diff --git a/bin/debug-trace-server/src/rpc_service.rs b/bin/debug-trace-server/src/rpc_service.rs index f17a5291..e5e9c0aa 100644 --- a/bin/debug-trace-server/src/rpc_service.rs +++ b/bin/debug-trace-server/src/rpc_service.rs @@ -20,7 +20,7 @@ use stateless_core::chain_spec::ChainSpec; use tracing::{trace, warn}; use crate::{ - admission::{AdmissionError, AdmissionLimiter, ExecutionPermit, TraceWeight}, + admission::{AdmissionError, AdmissionLimiter, ExecutionPermit}, data_provider::{ BlockData, DataProvider, DataProviderError, SLOW_STAGE_THRESHOLD_MS, TimeoutStage, }, @@ -31,7 +31,7 @@ use crate::{ ResponseSizeMetrics, RpcGlobalMetrics, SingleFlightMetrics, }, raw_json::RawJson, - response_cache::{CachedResource, RequestShape, ResponseCache, ResponseVariant}, + response_cache::{CachedResource, RequestShape, ResponseCache, ResponseVariant, TraceWeight}, tracing_executor::TraceError, }; @@ -312,6 +312,37 @@ impl RpcContext { Ok(BlockLookup::Fetched(data, permit)) } + /// [`Self::lookup_block_by_number`]'s by-hash sibling: the requested hash *is* the cache + /// key, so there is no resolution step, but the rest of the order is identical and is the + /// part worth not re-deriving per handler — consult the cache, then take an execution + /// permit only on a miss, then fetch under the same deadline the permit wait was clamped to. + async fn lookup_block_by_hash( + &self, + method: &'static str, + resource: CachedResource, + variant: Option, + weight: TraceWeight, + block_hash: B256, + start: Instant, + ) -> Result { + if let Some(cached) = + check_cache(&self.response_cache, resource, block_hash, variant, method, start) + { + return Ok(BlockLookup::Cached(cached)); + } + + // Minted once and used for both the permit wait and the fetch, so the queue is carved + // out of the request's budget rather than added on top of it. + let deadline = self.data_provider.fetch_deadline(); + let permit = self.acquire_execution(method, weight, deadline).await?; + let data = self + .data_provider + .get_block_data_by_hash(block_hash, deadline) + .await + .map_err(|e| data_provider_failure(method, &e))?; + Ok(BlockLookup::Fetched(data, permit)) + } + /// Waits for an execution permit, or refuses when the wait would outlast the budget. /// /// `deadline` must be the same one the request's fetch will run under, so the wait is @@ -326,7 +357,7 @@ impl RpcContext { ) -> Result, jsonrpsee::types::ErrorObjectOwned> { let Some(limiter) = &self.admission else { return Ok(None) }; let cutoff = self.data_provider.permit_cutoff(deadline); - match limiter.acquire_execution(method, weight.is_heavy(), cutoff).await { + match limiter.acquire_execution(method, weight, cutoff).await { Ok(permit) => Ok(Some(permit)), Err(AdmissionError::Overloaded) => Err(overloaded_err(method)), } @@ -374,10 +405,10 @@ fn rpc_err(msg: String) -> jsonrpsee::types::ErrorObjectOwned { } /// Creates a JSON-RPC invalid-params error (code -32602). -fn invalid_params_err(msg: String) -> jsonrpsee::types::ErrorObjectOwned { +pub(crate) fn invalid_params_err(msg: impl Into) -> jsonrpsee::types::ErrorObjectOwned { jsonrpsee::types::ErrorObjectOwned::owned( jsonrpsee::types::error::INVALID_PARAMS_CODE, - msg, + msg.into(), None::<()>, ) } @@ -407,11 +438,7 @@ fn classify_and_gate( /// sides itself through `metrics::record_admission_shed`. fn overloaded_err(method: &'static str) -> jsonrpsee::types::ErrorObjectOwned { metrics::record_rpc_error(method, ErrorReason::Overloaded); - jsonrpsee::types::ErrorObjectOwned::owned( - crate::admission::QUEUE_FULL_CODE, - crate::admission::QUEUE_FULL_MESSAGE, - None::<()>, - ) + crate::admission::queue_full_error() } /// Maps a [`DataProviderError`] to a JSON-RPC error object. @@ -488,8 +515,8 @@ fn compute_block_trace( // Request-attributable, not data-attributable: the block is fine, the client asked for // more output than this process will hand back. That discriminant is what keeps an // oversized request from evicting a perfectly good block from the data cache. - let json = check_response_size(json, method_name, max_response_size) - .map_err(|e| TraceError::Request(e.to_string()))?; + let json = + check_response_size(json, method_name, max_response_size).map_err(TraceError::Request)?; let serialize_ms = start.elapsed().as_millis() - trace_ms; let response_size = json.byte_len(); @@ -590,7 +617,7 @@ fn serialize_reply( // `TraceFailed` rather than `Internal`: the tracer ran and its output could not be // returned, which is exactly what that reason means. `Internal` stays "our fault". metrics::record_rpc_error(method_name, ErrorReason::TraceFailed); - rpc_err(e.to_string()) + rpc_err(e) })?; ResponseSizeMetrics::new_for_method(method_name).record(json.byte_len()); Ok(json) @@ -608,7 +635,7 @@ fn check_response_size( json: RawJson, method_name: &'static str, max_response_size: usize, -) -> Result { +) -> Result { let bytes = json.byte_len(); if bytes <= max_response_size { return Ok(json); @@ -621,24 +648,12 @@ fn check_response_size( max_response_size, "discarded a response over the configured size limit" ); - Err(ResponseTooLarge { bytes, max_response_size }) -} - -/// The over-limit rejection, rendered once so both serialization points word it identically. -struct ResponseTooLarge { - bytes: usize, - max_response_size: usize, -} - -impl std::fmt::Display for ResponseTooLarge { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - write!( - f, - "response of {} bytes exceeds the {}-byte limit; use a lighter tracer, or request \ - fewer blocks per batch", - self.bytes, self.max_response_size - ) - } + // Worded here rather than at the two call sites, so both serialization points say the same + // thing; each still classifies the failure its own way. + Err(format!( + "response of {bytes} bytes exceeds the {max_response_size}-byte limit; use a lighter \ + tracer, or request fewer blocks per batch" + )) } /// Records metrics and logs for a completed request. @@ -719,30 +734,20 @@ impl DebugTraceRpcServer for RpcContext { let opts = opts.unwrap_or_default(); let (variant, weight) = classify_and_gate(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, &opts)?; - // Check cache — the requested hash IS the key; no resolution step. - if let Some(cached) = check_cache( - &self.response_cache, - CachedResource::DebugTraceBlock, - block_hash, - variant, - METHOD_DEBUG_TRACE_BLOCK_BY_HASH, - start, - ) { - return Ok(cached); - } - - // Minted once and used for both the permit wait and the fetch, so the queue is carved - // out of the request's budget rather than added on top of it — total client latency - // stays bounded by `--block-fetch-timeout` however long the wait was. - let deadline = self.data_provider.fetch_deadline(); - let _permit = - self.acquire_execution(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, weight, deadline).await?; - - let data = self - .data_provider - .get_block_data_by_hash(block_hash, deadline) - .await - .map_err(|e| data_provider_failure(METHOD_DEBUG_TRACE_BLOCK_BY_HASH, &e))?; + let (data, _permit) = match self + .lookup_block_by_hash( + METHOD_DEBUG_TRACE_BLOCK_BY_HASH, + CachedResource::DebugTraceBlock, + variant, + weight, + block_hash, + start, + ) + .await? + { + BlockLookup::Cached(cached) => return Ok(cached), + BlockLookup::Fetched(data, permit) => (data, permit), + }; let block_num = data.block.header.number; let result = self.compute_debug_trace(&data, METHOD_DEBUG_TRACE_BLOCK_BY_HASH, opts)?; @@ -1298,7 +1303,7 @@ mod tests { let _held = limiter .acquire_execution( METHOD_DEBUG_TRACE_BLOCK_BY_HASH, - false, + crate::response_cache::TraceWeight::Normal, Instant::now() + Duration::from_secs(30), ) .await @@ -1320,7 +1325,7 @@ mod tests { let _held = limiter .acquire_execution( METHOD_DEBUG_TRACE_BLOCK_BY_HASH, - false, + crate::response_cache::TraceWeight::Normal, Instant::now() + Duration::from_secs(30), ) .await