diff --git a/docs/management/account_modes.mdx b/docs/management/account_modes.mdx index 10cfd508..3df1896e 100644 --- a/docs/management/account_modes.mdx +++ b/docs/management/account_modes.mdx @@ -202,6 +202,70 @@ Base RPC works, e.g. `https://mainnet.base.org` or prefers the wallet's RPC, so this fallback only matters for the brief window before `connectSigner(signer)` runs. +## Read-after-write staleness + +Each API-server instance keeps a **per-instance cache** on the +**action-execution** path. It caches on-chain **authorization decisions** — +whether an API key may execute a given action or use a given wallet in an +action — and the **wallet-derivation lookups** those checks depend on. An +event listener polls the chain for account-mutation events roughly every +**10 seconds** and **invalidates** the affected account's cached entries +when it sees a change. The node was deliberately built with a per-instance +listener rather than a single leader, so behind a load balancer there are N +independent caches, each catching up on its own poll. + +Two things are **not** cached and are therefore never stale: + +- **List/read endpoints** (`listApiKeys`, `listGroups`, `listWallets`, + `listActions`, ...) do a live contract call on every request, so they + reflect chain head (modulo your RPC node's own lag). This is true in API + mode and in sovereign mode (where reads go directly to the chain via your + RPC/signer). +- Anything you read to *display* configuration — the dashboard's tables of + keys, groups, wallets, and actions — is live for the same reason. + +The window bites on the **execute path**, and only when a permission change +lands **outside** the instance running the action — most commonly: + +- A **ChainSecured (sovereign) wallet write** (the contract emits the event; + no API server originated it, so every instance learns of it only on its + next poll). +- A write made through a **different API-server instance** behind the load + balancer. +- A transaction sent **directly to the contract**. + +> After such a write, an instance that hasn't yet observed the event can +> make the *pre-write* authorization decision when it runs an action: a +> **just-granted** permission may still be denied (403), or a **just-revoked** +> permission may still succeed. Behind a load balancer, consecutive +> executions can hit different instances and briefly disagree. + +How long the stale decision can persist: + +- **Listener healthy:** until its next poll observes the event and + invalidates — at most ~one poll interval (**~10s**). +- **Listener stalled or dead:** the cache still self-heals via TTL — stale + **denials** clear within **30s**, stale **grants** within **5 minutes**. + A dead listener regresses the window to those TTLs; it is never open-ended. + +If you need a permission change to take effect immediately everywhere, +wait out one poll interval (~10s) before relying on the new authorization +on the execute path. + + +A healthy instance keeps its listener lag at or below the poll interval. The +unauthenticated `GET /core/v1/health` endpoint reports +`account_event_listener_lag_seconds` (`null` until the listener's first +poll). A value that stays well above ~10s means that instance's listener is +stalled or dead, so cache invalidation has stopped and execute-path +authorization falls back to the TTL bounds above. The Chipotle Dashboard +polls this and shows a staleness banner when an instance reports more than +30s of lag. (Caveat: the lag resets to ~0 whenever the listener process +restarts, even though a restart skips events emitted while it was down — +those are covered only by TTL expiry — so treat the metric as a liveness +signal, not a guarantee that no event was missed.) + + ## Using the dashboard The Chipotle Dashboard offers both modes side-by-side on the login screen: diff --git a/docs/management/dashboard.mdx b/docs/management/dashboard.mdx index 04f676a2..cef31862 100644 --- a/docs/management/dashboard.mdx +++ b/docs/management/dashboard.mdx @@ -74,6 +74,32 @@ async function main({ pkpId }) { ``` Choose the API key (account or usage key) to use for the request, then click **Execute**. The node runs the action and returns signatures, response, and logs. The key you use must be allowed to run that action (via the group and IPFS CID configuration). +## When a permission change takes a moment to apply + +The dashboard's tables (keys, groups, wallets, actions) read live from the +chain, so they always show current state. But **running an action** goes +through a short-lived per-server authorization cache that a listener keeps +in sync by polling the chain about every **10 seconds**. + +So right after a permission change lands on-chain — especially a +**ChainSecured (wallet-signed) write**, or a change made from another +device or directly against the contract — there's a brief window where the +server that runs your action may still apply the *previous* permissions: a +**just-granted** permission can still be rejected, or a **just-revoked** one +can still work. It resolves on its own within a few seconds. If a run's +result surprises you right after a permission change, wait a moment and try +again. + + +If a server is having trouble keeping up, the dashboard shows an amber +banner near the top of the page: *"This server is catching up to recent +on-chain changes..."* It means that server is more than 30 seconds behind on +syncing permission changes, so recently changed permissions may take longer +than usual to take effect when you run actions (the tables you see stay +accurate). The banner clears automatically once the server catches up — no +action is needed on your part. + + ## Daily Usage The dashboard is just your human-friendly configuration tool. Once your account and keys are set up to your liking, you can simply call the lit-action endpoint with your usage key each time you, your dApp or cron job needs to execute a lit action. So the only daily use step is diff --git a/lit-actions/tests/it.rs b/lit-actions/tests/it.rs index 642912ac..f2826500 100644 --- a/lit-actions/tests/it.rs +++ b/lit-actions/tests/it.rs @@ -160,6 +160,22 @@ impl TestClient { #[ctor::ctor] fn init() { + // Cap the pre-warmed worker pool for the whole test process. Every + // `TestServer::start()` warms this many workers, and ~a dozen + // server-spawning tests run in parallel; at the production default (10) + // that is a ~120-way concurrent V8-snapshot bootstrap storm which, on a + // loaded/constrained CI runner, can starve the warmup gate so that not even + // one worker becomes ready within the timeout (see `wait_for_warmup`, + // `pool_warm_hit`, `pool_memory_limit_bypass`). A small pool still exercises + // pool hits, refills, and fallbacks. Respect an explicit override — e.g. + // `LIT_ACTIONS_POOL_SIZE=0` to run these tests with the pool disabled. + if std::env::var_os("LIT_ACTIONS_POOL_SIZE").is_none() { + // SAFETY: a `#[ctor]` runs once during process initialization, before + // any test thread, server, or worker exists, so there is no concurrent + // reader/writer of the environment here. + unsafe { std::env::set_var("LIT_ACTIONS_POOL_SIZE", "2") }; + } + // Set RUST_LOG to get logs during testing pretty_env_logger::init(); @@ -1096,14 +1112,14 @@ async fn wait_for_warmup(pool_health: &Arc, target: usize) { if target == 0 { return; } - let deadline = std::time::Instant::now() + std::time::Duration::from_secs(15); + let deadline = std::time::Instant::now() + std::time::Duration::from_secs(30); loop { if pool_health.ready() >= 1 { return; } assert!( std::time::Instant::now() < deadline, - "no pre-warmed worker became ready within 15s (target={target})", + "no pre-warmed worker became ready within 30s (target={target})", ); tokio::time::sleep(std::time::Duration::from_millis(10)).await; } @@ -1191,8 +1207,9 @@ async fn pool_memory_limit_bypass() { ); } -/// Concurrent execution: 20 in-flight requests against a pool of 10. Mix -/// of pool hits and legacy fallbacks; all must succeed without deadlock. +/// Concurrent execution: 20 in-flight requests against a small pre-warmed +/// pool. Mix of pool hits and legacy fallbacks; all must succeed without +/// deadlock, regardless of how many requests land on a warm worker. #[tokio::test] async fn pool_concurrent_exhaustion() { use deno_runtime::deno_core::futures::future::join_all; diff --git a/lit-api-server/src/account_events.rs b/lit-api-server/src/account_events.rs index ad681325..c5e54083 100644 --- a/lit-api-server/src/account_events.rs +++ b/lit-api-server/src/account_events.rs @@ -20,7 +20,8 @@ use alloy::providers::Provider; use alloy::rpc::types::Filter; use alloy::sol_types::SolEvent; use std::collections::HashSet; -use std::time::Duration; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::{Duration, SystemTime, UNIX_EPOCH}; /// Polling interval for checking new account-mutation events. const EVENT_POLL_INTERVAL: Duration = Duration::from_secs(10); @@ -36,6 +37,54 @@ const DEAD_WARN_INTERVAL: Duration = Duration::from_secs(300); /// listener is invisible after its single startup-failure error scrolls away. const LISTENER_UP_GAUGE: &str = "account_event_listener.up"; +/// Wall-clock unix-seconds at which the listener last confirmed it was current +/// with the chain head (either after processing a batch of logs, or after +/// observing that no new blocks had been produced). `0` means it has not yet +/// completed a poll — i.e. the listener never started or is still on its first +/// iteration. Updated with [`Ordering::Relaxed`]: this is a monotonic-ish +/// liveness timestamp, not a synchronization point, and a few hundred +/// milliseconds of staleness in the reported lag is immaterial. +/// +/// Process-global: only [`mark_caught_up`] writes it (from the single listener +/// task). Any test that mutates it races every other test, so keep such tests +/// to one (see the `listener_lag_*` unit test) or serialize them. +static LAST_CAUGHT_UP_UNIX_SECS: AtomicU64 = AtomicU64::new(0); + +fn now_unix_secs() -> u64 { + SystemTime::now() + .duration_since(UNIX_EPOCH) + .map(|d| d.as_secs()) + .unwrap_or(0) +} + +/// Record that the listener is current with the chain head as of now. +fn mark_caught_up() { + LAST_CAUGHT_UP_UNIX_SECS.store(now_unix_secs(), Ordering::Relaxed); +} + +/// Seconds since the account-event listener last confirmed it was current with +/// the chain head, or `None` if it has not yet completed a poll. +/// +/// Healthy values stay at or below the poll interval (~10s). A value that climbs +/// well above it means the listener is stalled (RPC errors, a slow `eth_getLogs`) +/// or has died — in which case on-chain account mutations are no longer +/// invalidating the per-instance execute-path authorization cache, so a +/// just-changed permission can take until that cache's TTL to apply on this +/// instance. Exposed (unauthenticated) via `GET /core/v1/health` as +/// `account_event_listener_lag_seconds` so clients/ops can surface staleness. +/// +/// Caveat: this measures time-since-last-poll, not events-missed. It resets to +/// ~0 whenever the listener (re)starts — and a restart skips events emitted +/// while it was down (those are covered only by cache TTL expiry) — so treat it +/// as a liveness signal, not proof that every mutation was observed. +pub fn listener_lag_seconds() -> Option { + let last = LAST_CAUGHT_UP_UNIX_SECS.load(Ordering::Relaxed); + if last == 0 { + return None; + } + Some(now_unix_secs().saturating_sub(last)) +} + /// Expand `$mac!(EventType, |e| vec![..account hashes..])` once per `WritesFacet` /// account/permission mutation event. Used to build both the log filter's topic /// set and the decode dispatch from a single source of truth, so the two can @@ -230,6 +279,10 @@ async fn run_event_listener() -> anyhow::Result<()> { "Account event listener started" ); metrics::gauge!(LISTENER_UP_GAUGE).set(1.0); + // We've just read the chain head, so we're current as of now. Seeds the lag + // gauge so `/health` reports a real lag immediately rather than `null` until + // the first poll tick fires one interval later. + mark_caught_up(); let mut last_checked_block = start_block.saturating_sub(1); let mut interval = tokio::time::interval(EVENT_POLL_INTERVAL); @@ -247,6 +300,8 @@ async fn run_event_listener() -> anyhow::Result<()> { }; if latest_block <= last_checked_block { + // No new blocks since the last poll — already current with the head. + mark_caught_up(); continue; } @@ -265,6 +320,8 @@ async fn run_event_listener() -> anyhow::Result<()> { // Only advance once logs are successfully processed; on error we // retry the same range on the next tick. last_checked_block = latest_block; + // Processed everything up to the head we observed this tick. + mark_caught_up(); } Err(e) => { tracing::warn!( @@ -394,6 +451,28 @@ mod tests { assert_eq!(account_hashes_from_log(&removed), vec![account, usage]); } + #[test] + fn listener_lag_reports_none_until_first_poll_then_small() { + // The listener never starts in unit tests, and this static is touched by + // no other test, so we own it here. `0` (never polled) reads as None. + LAST_CAUGHT_UP_UNIX_SECS.store(0, Ordering::Relaxed); + assert_eq!(listener_lag_seconds(), None); + + // After a successful poll the lag is the elapsed wall-clock time, which + // is ~0 immediately after marking. + mark_caught_up(); + let lag = listener_lag_seconds().expect("lag is Some after a poll"); + assert!(lag <= 2, "fresh lag should be near zero, got {lag}"); + + // A stale timestamp surfaces as a large lag rather than wrapping. + LAST_CAUGHT_UP_UNIX_SECS.store(now_unix_secs().saturating_sub(120), Ordering::Relaxed); + let lag = listener_lag_seconds().expect("lag is Some"); + assert!( + lag >= 120, + "stale lag should reflect elapsed time, got {lag}" + ); + } + #[test] fn unknown_event_yields_no_hashes() { // A billing event emitted by the same contract is not a WritesFacet diff --git a/lit-api-server/src/core/v1/health.rs b/lit-api-server/src/core/v1/health.rs index 132822c6..f13ec87e 100644 --- a/lit-api-server/src/core/v1/health.rs +++ b/lit-api-server/src/core/v1/health.rs @@ -44,6 +44,17 @@ pub struct HealthResponse { pub lit_actions_gvisor_reachable: bool, pub cpu_available: bool, pub billing_keys_present: bool, + /// Seconds since the on-chain account-event listener last confirmed it was + /// current with the chain head, or `null` if it has not yet completed a poll. + /// Healthy values sit at or below the ~10s poll interval; a large value means + /// this instance's execute-path authorization cache is no longer being + /// invalidated by on-chain writes, so a just-changed permission can take + /// until the cache TTL (30s for denials, 5min for grants) to take effect on + /// this instance. Informational only — does NOT affect the health status (a + /// lagging listener still serves traffic; list/read endpoints stay live + /// regardless). Clients (e.g. the dashboard) surface a staleness banner when + /// this exceeds 30s. + pub account_event_listener_lag_seconds: Option, } pub fn routes() -> Vec { @@ -64,9 +75,11 @@ async fn health( let cpu_available = !cpu_monitor.is_overloaded(); let billing_keys_present = stripe_state.is_some(); + let account_event_listener_lag_seconds = crate::account_events::listener_lag_seconds(); // Only lit_actions_reachable + cpu_available gate health. - // billing_keys_present and lit_actions_gvisor_reachable are informational. + // billing_keys_present, lit_actions_gvisor_reachable, and + // account_event_listener_lag_seconds are informational only. let healthy = lit_actions_reachable && cpu_available; let status = if healthy { @@ -82,6 +95,7 @@ async fn health( lit_actions_gvisor_reachable, cpu_available, billing_keys_present, + account_event_listener_lag_seconds, }), ) } @@ -191,6 +205,31 @@ mod tests { assert!(body.cpu_available); } + #[tokio::test] + async fn health_always_serializes_listener_lag_field() { + // The field is always present in the JSON (as a number or `null`) so + // clients can rely on its key. We assert on the raw body rather than the + // deserialized value because the lag is backed by a process-global the + // account_events unit tests also exercise — asserting a specific value + // here would race with them. (`Option` would silently deserialize a + // missing key as `None`, so a deserialize round-trip can't prove the key + // is emitted.) + let client = Client::tracked(build_rocket(false, None)) + .await + .expect("valid rocket"); + let body = client + .get("/health") + .dispatch() + .await + .into_string() + .await + .expect("body"); + assert!( + body.contains("account_event_listener_lag_seconds"), + "health body must always include the listener-lag key, got: {body}" + ); + } + #[tokio::test] async fn health_reports_lit_actions_unreachable_when_no_socket() { let client = Client::tracked(build_rocket(false, None)) diff --git a/lit-static/core_sdk.js b/lit-static/core_sdk.js index e52e80fc..6fe63eff 100644 --- a/lit-static/core_sdk.js +++ b/lit-static/core_sdk.js @@ -17,6 +17,21 @@ * `rpcUrl` or a signer that carries its own provider (any ethers v6 signer * with `signer.provider` set). The dashboard typically calls * `getNodeChainConfig()` first and passes the values in. + * + * Read-after-write staleness: list/read methods (`listApiKeys`, `listGroups`, + * `listWallets`, `listActions`, ...) are NOT cached — they do a live contract + * call and reflect chain head in both modes. The per-instance cache sits on the + * action-execution path (authorization decisions + wallet-derivation lookups), + * and an event listener invalidates it by polling the chain ~every 10s. So after + * an on-chain write the server didn't originate — most commonly a ChainSecured + * (sovereign) wallet write, or a write via another API-server instance — a + * just-granted permission may still be denied, or a just-revoked one may still + * succeed, when running an action, for up to ~one poll interval (~10s) while the + * listener is healthy (or up to the cache TTL — 30s for denials, 5min for grants + * — if it is stalled). Behind a load balancer, consecutive executions can hit + * different instances and briefly disagree. The `GET /core/v1/health` endpoint + * reports `account_event_listener_lag_seconds` to detect a lagging instance. + * See docs/management/account_modes.mdx ("Read-after-write staleness"). */ import { ACCOUNT_CONFIG_VIEW_ABI } from './account_config_view_abi.js'; diff --git a/lit-static/dapps/dashboard/app.js b/lit-static/dapps/dashboard/app.js index 90887802..a8228c50 100644 --- a/lit-static/dapps/dashboard/app.js +++ b/lit-static/dapps/dashboard/app.js @@ -13,6 +13,7 @@ import { initActions, loadActions } from './actions.js'; import { initWallets, loadWallets } from './wallets.js'; import { initActionRunner } from './runner.js'; import { initAbout } from './about.js'; +import { startListenerLagMonitor } from './listener_lag.js'; // ----- Preload all tables (with error visibility) ----- @@ -284,6 +285,9 @@ function onAuthReady() { refreshChangeOwnershipVisibility(); updateChainSecuredRpcUrlUI(); handleBillingReturn(); + // Watch the connected server's account-event listener and warn if its cache + // is lagging the chain (reads may be stale). Idempotent across re-auths. + startListenerLagMonitor(); } // ----- Init ----- diff --git a/lit-static/dapps/dashboard/index.html b/lit-static/dapps/dashboard/index.html index c7810c04..915671bc 100644 --- a/lit-static/dapps/dashboard/index.html +++ b/lit-static/dapps/dashboard/index.html @@ -184,6 +184,10 @@

+ + +