test(cketh): [experiment] strip added fixture helpers to expose implicit-mock dependencies - #10959
Conversation
Removes the helpers PR #10955 added on top of the mechanical StateMachine -> PocketIC port that have no equivalent in the pre-migration fixture: drain_startup_http_outcalls, drain_stray_latest_block_refresh_calls, is_latest_block_refresh, the OutcallPolicy/await_call_draining_outcalls split, and find_rpc_call_retrying. Call sites fall back to the plain StateMachine-era equivalents (a single-pass stop_ongoing_https_outcalls, PocketIc::await_call, a 10-tick find_rpc_call poll). Integration test failures are expected and intentionally left unfixed: this branch is an analysis instrument to catalog which tests implicitly depended on the removed machinery, ahead of deciding whether to reintroduce explicit mocks instead. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
| // time a test advances time by `SCRAPING_ETH_LOGS_INTERVAL` (3 minutes). | ||
| drain_startup_http_outcalls(&cketh.env); | ||
|
|
||
| cketh |
There was a problem hiding this comment.
🤖🧐 🟠 Removing drain_startup_http_outcalls is the first-order cause of all 23 cketh_test failures, and it is forced by a real harness difference rather than being optional machinery.
Probe evidence (should_retrieve_minter_info): at this point 8 outcalls are pending and never answered — ids 0-3 ["finalized"] (startup scrape) and ids 4-7 ["latest"] (startup refresh). The first advance_time(SCRAPING_ETH_LOGS_INTERVAL) (180 s) crosses CANISTER_HTTP_TIMEOUT_INTERVAL = 60 s (rs/types/types/src/canister_http.rs:80), so Provider1's stub answers a stale startup request, and the very next tick() times out the other 7 at once. Provider2's stub then sees an empty list — hence Current requests is empty in every one of the 23 panics, which refutes the "refresh call occupies the slot" hypothesis.
ic-state-machine-tests never times these out, so on StateMachine the 8 contexts sat there forever in CallbackId order and the stubs deterministically consumed the 4 ["finalized"] ones. That is why the original fixture needed no drain.
Note the drain must reject, not answer: answering with real block responses would set last_observed_block_number, breaking tests/cketh.rs:1201 and tests/ckerc20.rs:1891. Recommend keeping this helper.
| pub fn stop_ongoing_https_outcalls(&self) { | ||
| for _ in 0..MAX_TICKS { | ||
| if self.drain_pending_https_outcalls() { | ||
| return; | ||
| } | ||
| // The block height refresh timer can be mid-backoff after hitting ic-cdk-timers' | ||
| // per-timer concurrent-call cap (see | ||
| // `JsonRpcRequestMatcher::find_rpc_call_retrying` in mock.rs), with nothing | ||
| // currently pending for us to drain; nanosecond ticking can't cross that gap, so | ||
| // jump forward to give it a chance to resurface before giving up. | ||
| self.env | ||
| .advance_time(ic_cketh_minter::REFRESH_LATEST_BLOCK_HEIGHT_INTERVAL); | ||
| } | ||
| panic!( | ||
| "failed to drain pending https outcalls after {MAX_TICKS} attempts, still pending: {}", | ||
| mock::debug_http_outcalls(&self.env) | ||
| ); | ||
| } | ||
|
|
||
| fn drain_pending_https_outcalls(&self) -> bool { | ||
| for _ in 0..MAX_TICKS { | ||
| let requests = self.env.get_canister_http(); | ||
| if requests.is_empty() { | ||
| return true; | ||
| } | ||
| for request in requests { | ||
| reply_500(&self.env, &request); | ||
| } | ||
| self.env.tick(); | ||
| for request in self.env.get_canister_http() { | ||
| reply_500(&self.env, &request); | ||
| } | ||
| false | ||
| self.env.tick(); |
There was a problem hiding this comment.
🤖🧐 🔴 This single-pass drain cannot work on PocketIC, and this — not "the refresh timer re-fires in the gap" — is what deadlocks all 37 ckerc20_test setups.
Probe of stop_minter inside CkErc20Setup::new (should_not_scrape_when_no_erc20_token):
- 1st
stop_minter(add_orchestrator_id): 8 requests pending, drained, settles at round 1. ✓ upgrade_canister+start_minter→post_upgradere-runssetup_timers()→ 8 new outcalls (ids 8-15: 4["finalized"]+ 4["latest"]) created in that same round.- 2nd
stop_minter:get_canister_http()here logs empty — PocketIC does not surface requests created in a round that has not been ticked. This loop answers nothing, then ticks; only after that tick do all 8 appear. - The minter is now
Stoppingholding 8 unanswered outcalls. Ticks advance ~1 ns, so the 60 s http timeout never rescues it either → deadlock →await_callgives up at 100 rounds.
Two corrections to the catalog: it is not a re-fire in a gap (the calls already existed, just invisible), and it is not refresh-specific (half are the scrape's ["finalized"]). Consequence for the decision: explicit per-test mocks cannot fix this cluster — there is nothing to stub at the moment the drain runs, and the path is CkEthSetup::upgrade_minter, reachable only through the fixture.
Empirically, replacing this body with a plain for _ in 0..MAX_TICKS { drain; tick; } alone takes ckerc20_test from 3/40 to 20/40. Recommend keeping a bounded drain loop here (the catalog's option (b)), simplified to an early return on two consecutive empty polls.
| && json_rpc_request.params == json!(["latest", false]) | ||
| } | ||
| Err(_) => false, | ||
| .unwrap_or(true) |
There was a problem hiding this comment.
🤖🧐 🟠 This unwrap_or(true) restores the original fallback faithfully, but it is the reason the explicit-mock route costs more than the catalog estimates.
Ablation: with the two drains restored but this left as unwrap_or(true), cketh_test is 5/26; restoring is_latest_block_refresh here takes it to 24/26. So this is the highest-leverage single helper in the stripped set.
The blast radius of replacing it with explicit mocks is not "one line in a builder". matches short-circuits here on None → true, and find_rpc_call takes the first match in get_canister_http() order — so an unconstrained scrape stub and an explicit ["latest"] stub are ambiguous by construction: whichever request comes first in the vec wins. Disambiguating means adding .with_request_params(json!(["finalized", false])) to every currently-unconstrained scrape stub — all 19 MockJsonRpcProviders::when(EthGetBlockByNumber) sites (13 in tests/cketh.rs, 5 in tests/ckerc20.rs, plus flow.rs:337 and test_utils/src/ckerc20.rs:784) — i.e. restating in 19 places the invariant this helper states once (G5).
(Ordering itself is not the problem: get_canister_http() preserves creation order — observed ids 0..7 in order — matching StateMachine's BTreeMap<CallbackId, _> iteration.)
Suggested middle ground that keeps Greg's "explicit mock" instinct without the 19-site edit: default the builder's params to ["finalized", false] (or add a for_scrape()), so the intent lives on the stub and this fallback disappears entirely.
|
|
||
| fn expect_rpc_call(self, env: &PocketIc) { | ||
| let request = self.matcher.find_rpc_call_retrying(env).unwrap_or_else(|| { | ||
| let request = self.matcher.find_rpc_call(env).unwrap_or_else(|| { |
There was a problem hiding this comment.
🤖🧐 🔵 On the removed find_rpc_call_retrying: its premise is real — the minter log does emit [ic-cdk-timers] canister_global_timer: too many concurrent calls for single timer (5), rescheduling for next possible execution time, exactly as its comment claimed. So it was not invented.
But it is also the piece the failure data justifies least: once the startup drain, the stop-drain loop, and the is_latest_block_refresh exclusion are in place, cketh_test is already at 24/26 with this helper absent. And it burns up to 180 s of simulated time on every lookup — a large hidden side effect for something named find_*, which its own comment concedes makes it unusable for negative expectations.
Same recommendation as for OutcallPolicy: re-run #10955 without it and keep it only for the specific tests that then fail, as a named list rather than a blanket policy in expect_rpc_call.
|
🤖🧐 ANALYSIS: PARTIALLY CONFIRMED — counts and per-test lists reproduce exactly; both root-cause mechanisms are wrong. Net: the two drains are forced by real PocketIC-vs-StateMachine semantic gaps and must stay; Evidence, ablation table, and per-cluster analysis1. Was the strip faithful? — YESChecked line-by-line against Two fidelity footnotes (neither can manufacture failures):
2. Counts — reproduced exactly
3. Cluster A (cketh_test) — mechanism REFUTED, effect real but second-orderCatalog: the unconstrained Instrumented run of
The catalog's refresh-collision effect is real, just downstream. Ablation (each variant run against both suites, then reverted):
Also confirmed genuine: the minter log emits 4. Cluster B (ckerc20_test) — mechanism REFUTED, conclusion upheldCatalog: the refresh timer re-fires a fresh outcall in the gap between the single reply pass and the canister settling. Instrumented
So it is not a re-fire in a gap and not refresh-specific — half the stuck calls are the scrape's 5. Decision guidanceCan cluster A be fixed with explicit per-test mocks? Partly — but it is per-test surgery, not a one-line builder addition, and it does not remove the need for the startup drain.
Net recommendation (hybrid). Keep, as forced by PocketIC semantics:
Re-measure before keeping (the failure data does not justify these):
6. What the catalog missed
|
CkEthSetup::new ended with an update call backing the MINTER_ADDRESS assertion. That call executes the rounds which let the minter's genesis timers fire, so every fixture-built test inherited eight canister-http outcalls pending at genesis time. Those requests cross PocketIC's 60s outcall timeout as soon as a test advances time, which is what the stripped fixture machinery was compensating for. Moving the assertion into its own test takes this branch from 3/26 to 20/27 passing without reintroducing any fixture machinery. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
🤖 New commit What actually creates the dangling genesis outcalls: The three installs produce nothing; Effect of moving the assertion into its own test (
Remaining 7 failures, a genuinely different population needing separate diagnosis: Note for the design decision: answering the genesis outcalls with explicit per-test mocks is not state-equivalent to the fixture rejecting them — a reply to the |
stop_minter answered the pending HTTPS outcalls in the same round it submitted the stop request, so the drain ran before the minter had left the Running state. The outcalls its timers issue in that last running round only become visible afterwards, and await_call offers no point at which a test can answer them, so the stop waited on eight call contexts that nobody could close. Ticking once between the two lets the stop take effect first. The minter issues no further outcalls while stopping, so a single drain pass then suffices. cketh_test goes from 20/27 to 24/27 passing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…calls Advancing time past CANISTER_HTTP_TIMEOUT_INTERVAL kills the outcalls still in flight, but get_canister_http keeps listing them until a round processes the timeouts. A stub could therefore bind to a request that is already dead and see its response discarded, leaving the request issued by the next scraping cycle unanswered. Ticking once before polling settles those requests first. The two block number stubs in should_panic_when_last_finalized_block_in _the_past also went unconstrained, so they could answer the block height refresh timer's query for the latest block instead of the finalized block the scraping cycle waits for. cketh_test goes from 24/27 to 25/27 passing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The minter derives its Ethereum address from a timer scheduled at install, so the address is only known once the canister has executed a few rounds. A freshly built fixture has executed none, which is what the deposit flow relies on: it expects to trigger the first scraping cycle itself. Ticking to derive the address beforehand costs that cycle to TimerGuard AlreadyProcessing and breaks the flow. Assert instead what holds at each point: no address before the minter has run, and the derived address after the deposit. The value itself stays covered by should_derive_minter_address. cketh_test goes from 25/27 to 26/27 passing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The two block number stubs went unconstrained, so they could answer the block height refresh timer's query for the latest block and leave the finalized block the scraping cycle waits for unanswered. The scrape then never reached eth_getLogs. cketh_test is now fully green at 27/27. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The deposit flow's block number stub went unconstrained, so it could answer the block height refresh timer's query for the latest block and leave the finalized block the scraping cycle waits for unanswered. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Registering the ERC-20 tokens drives the minter through several rounds, so unlike the ckETH fixture the ckERC20 one hands over a minter that has a scraping cycle in flight. Advancing time then leaves that cycle holding the scraping TimerGuard, so the firing due at the new time is dropped as AlreadyProcessing and the expected block number query is never issued. Answering the query the pending cycle waits for lets it finish and release the guard. Responding with the block number already scraped keeps it from scraping logs nobody mocked. The block number stub that follows also went unconstrained and could answer the block height refresh timer's query instead of the finalized one. ckerc20_test goes from 22/40 to 37/40 passing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Analysis instrument, not intended for merge as-is. PR #10955 migrated the cketh integration tests from StateMachine to PocketIC and, alongside the mechanical port, added extra fixture machinery with no counterpart in the pre-migration StateMachine fixture:
drain_startup_http_outcalls,drain_stray_latest_block_refresh_calls,is_latest_block_refresh, theOutcallPolicy/await_call_draining_outcallssplit, andfind_rpc_call_retrying's retry/jump-forward behavior. The hypothesis under test: some of the tests this machinery was propping up could instead be adapted with explicit mocks that represent real productive scenarios (e.g. explicitly stubbing the minter's periodic latest-block-refresh JSON-RPC calls), keeping the fixture lean and closer to the original.This branch removes that machinery, leaves the crate compiling cleanly, and lets the affected integration tests fail on purpose so the failures can be cataloged and reviewed before deciding whether to reintroduce fixture machinery or add targeted explicit mocks per test. Tests are intentionally red — do not fix them here.
Kept vs removed
Removed (no counterpart in the pre-migration StateMachine fixture):
drain_startup_http_outcallsand its call inCkEthSetup::newdrain_stray_latest_block_refresh_callsand its call inupgrade_minteris_latest_block_refresh(mock.rs) and its uses inJsonRpcRequestMatcher::matches's fallback and the request-polling loopOutcallPolicyenum,poll_for_call,await_call,await_call_draining_outcalls— call sites now use the realPocketIc::await_call(per the API mappingawait_ingress(id, MAX_TICKS)→await_call(id)) or the simplifiedstop_ongoing_https_outcallsfind_rpc_call_retrying's retry/jump-forward loop —expect_rpc_callnow uses the plainfind_rpc_callstop_ongoing_https_outcalls's retry loop and itsdrain_pending_https_outcallshelper — reduced to the original's single reply-500-then-move-on passREJECT_CODE_SYS_TRANSIENTconst andreject_stray_http_outcallhelperKept (straightforward API-mapping ports, not the target machinery):
update_call/query_callwrappers, canister create/install/cycles plumbingsubmit_stop_minter(the plainsubmit_call_with_effective_principalport ofstop_canister_non_blocking)try_stop_minter_without_stopping_ongoing_https_outcalls(a direct, non-machinery port)find_rpc_call's plain 10-ticktick_until_next_http_requestpoll, matching the originalreply_500andREJECT_CODE_SYS_FATAL(used by the size-limit-exceeded response path, itself a direct port)Failure catalog
Verification:
cargo checkclean,cargo clippy(project's pinned invocation) clean,//rs/ethereum/cketh/test_utils:lib_testspasses. Both integration suites below are intentionally red.//rs/ethereum/cketh/minter:integration_tests_tests/cketh_test— 3 passed / 23 failedAll 23 failures panic at the same site,
test_utils/src/mock.rs:179insideStubOnce::expect_rpc_call, with "no request found matching the stub ... EthGetBlockByNumber ...":should_block_withdrawal_to_blocked_address,should_mint_when_1_error_with_3_out_of_4_strategy,should_block_deposit_from_blocked_address,should_not_overlap_when_scrapping_logs,should_not_finalize_transaction_when_receipts_do_not_match,should_fail_to_withdraw_too_small_amount,cketh_evm_rpc::should_retrieve_block_number,should_fail_to_withdraw_when_insufficient_funds,should_not_send_eth_transaction_when_fee_history_inconsistent,should_deposit_and_withdraw,should_not_mint_when_logs_too_inconsistent,should_half_range_of_scrapped_logs_when_response_over_two_mega_bytes,should_fail_to_withdraw_without_approval,should_be_able_to_stop_canister_during_scraping,should_panic_when_last_finalized_block_in_the_past,should_resubmit_new_transaction_when_price_increased,should_reimburse,should_resubmit_transaction_as_is_when_price_still_actual,should_retry_from_same_block_when_scrapping_fails,should_scrap_one_block_when_at_boundary_with_last_finalized_block,should_retrieve_minter_info,should_retrieve_cache_transaction_price,should_skip_single_block_containing_too_many_events.Root-cause hypothesis: the minter runs a periodic timer (
REFRESH_LATEST_BLOCK_HEIGHT_INTERVAL) that issues its owneth_getBlockByNumber("latest")JSON-RPC outcall, unrelated to log scraping, purely to refresh a metric. Withis_latest_block_refreshremoved,JsonRpcRequestMatcher::matchesno longer excludes this call from an unconstrained stub (match_request_params: Nonenow falls back totruefor any request, matching the original StateMachine-era behavior). Most of these tests build a generic, unparameterizedEthGetBlockByNumberstub meant to answer the scrape-triggered call; that stub can instead match and consume the unrelated refresh call, or the refresh call can occupy the outcall slot long enough that the real scrape call never appears inside the fixture's fixedMAX_TICKS = 10polling budget, soexpect_rpc_callgives up.should_be_able_to_stop_canister_during_scrapingis the one exception with an explicit["finalized", false]stub — there the refresh call (always["latest", false]) can't be matched by the stub directly, so the same periodic call is instead starving the finite poll window rather than being consumed by it.Sketch of an explicit-mock fix: before triggering a flow that depends on a scrape-triggered
EthGetBlockByNumberstub, add a dedicatedMockJsonRpcProviders::when(EthGetBlockByNumber).with_request_params(json!(["latest", false])).respond_for_all_with(...)stub for the refresh call, consumed up front (mirroring the two tests that already do this explicitly attests/cketh.rs:842andtests/ckerc20.rs:258), so the scrape-only stub can no longer collide with it.//rs/ethereum/cketh/minter:integration_tests_tests/ckerc20_test— 3 passed / 37 failedAll 37 failures panic identically at
packages/pocket-ic/src/nonblocking.rs:1719, with(400, "BadIngressMessage(\"Failed to answer to ingress ... after 100 rounds.\")"):deposit_erc20::should_not_record_one_event_per_registered_deposit_address,deposit_erc20::should_record_address_to_deposit,deposit_erc20::should_trap_when_called_from_anonymous_principal,deposit_erc20::should_update_latest_block_height_and_never_decrease,should_add_ckusdc_and_ckusdt_to_minter_via_orchestrator,should_block_deposit_from_blocked_address,should_block_deposit_from_corrupted_principal,should_deposit_ckerc20,should_deposit_cketh_and_ckerc20,should_deposit_cketh_and_ckerc20_when_ledger_temporary_offline,should_fail_to_mint_from_unsupported_erc20_contract_address,should_mint_with_ckerc20_setup,should_not_change_address_of_other_contracts_when_adding_new_contract,should_not_scrape_when_no_erc20_token,should_retrieve_minter_info,should_retry_to_add_usdc_when_minter_stopped,should_scrape_from_last_scraped_after_upgrade,should_skip_single_block_containing_too_many_events, and all 19withdraw_erc20::*tests.Root-cause hypothesis:
CkErc20Setup::newcallsupgrade_minter_to_add_orchestrator_idthenupgrade_minter_to_add_erc20_helper_contract, each of which callsstop_minter.stop_mintersubmitsstop_canister, does a single reply-500-then-move-on pass over whatever HTTP outcalls are pending right now (stop_ongoing_https_outcalls, matching the original StateMachine fixture's single-payload behavior), then awaits completion via the realPocketIc::await_call. On PocketIC, if the block-height refresh timer re-fires a fresh outcall in the gap between that single reply pass and the canister settling, that new call is never answered, so the minter'sstop_canistercall stays blocked on it indefinitely; PocketIC's ownawait_callgives up after 100 rounds and the sync client panics client-side. Since almost everyckerc20test builds its fixture throughCkErc20Setup::default()/::new(), essentially all of them hit this during setup.Sketch of an explicit-mock fix: either (a) explicitly stub the refresh call's response before/around each
stop_minterinvocation during setup so it never becomes a fresh unanswered outcall, or (b) if the retry-until-stable behavior genuinely reflects a real operational scenario (the minter's timers keep firing while it's asked to stop), keep a bounded, explicitly-scoped retry instop_ongoing_https_outcallsitself rather than reaching for the more generalOutcallPolicymechanism — a call this task leaves to Greg's review of the tradeoff.🤖 Generated with Claude Code