Skip to content

Conversation

@MartinquaXD
Copy link
Contributor

@MartinquaXD MartinquaXD commented Dec 9, 2025

Description

Sometimes the test failed because the driver immediately returned the DeadlineExceeded error after receiving the /settle request. This is very odd since the deadline is quite generous (5 blocks) and not much happens between picking the deadline and sending the request. We only do a few DB operations but they only take ~30ms while we only mine blocks every 200ms or so.
After some debugging it became clear that the driver's and the autopilot's view of the current block are just different. When the autopilot picks the deadline block the driver has already seen a few more blocks. So when the request arrives at the driver it immediately aborts the submission.

    2025-12-09T09:59:43.622Z  WARN ethrpc::block_stream: stream yielded new block block=BlockInfo { number: 45, hash: 0x125f77548762c9a89508f8da285e3b610ae5feaeade38fb0b2796f22dbeb17d5, parent_hash: 0xfcd54a3f2f1fbca7818279d30606734b875248906a8c7d186a7710d868525f9f, timestamp: 1577836806, gas_limit: 10000000, gas_price: 2, observed_at: Instant { tv_sec: 276, tv_nsec: 591749612 } }
    2025-12-09T09:59:43.622Z DEBUG cache_maintenance{cache="uniswapv2"}: shared::recent_block_cache: automatically updating 1 entries
    2025-12-09T09:59:43.623Z DEBUG token_fetcher: driver::infra::tokens: updating settlement contract balances tokens=2
    2025-12-09T09:59:43.626Z DEBUG /solve{solver=test_solver auction_id=4}:simulation_gas_price: driver::infra::blockchain: return=Some(1050000002)
    2025-12-09T09:59:43.626Z DEBUG cache_maintenance{cache="uniswapv2"}: shared::recent_block_cache: dropping blocks older than 36 from cache
    2025-12-09T09:59:43.627Z DEBUG cache_maintenance{cache="uniswapv2"}: shared::recent_block_cache: cache was updated and now contains entries=1 items=1
    2025-12-09T09:59:43.649Z  INFO /solve{solver=test_solver auction_id=4}: driver::infra::observe: solved auction solved=Solved { id: Id { id: 3, merged_solutions: [0] }, score: Ether(991852623738566336), trades: {Uid(0xa0d50a2cc9c54b694330d7c4d622e07342ba61702e62d24ac9af2b0398b3e825b7f8bc63bbcad18155201308c8f3540b07f84f5effffffff): Amounts { side: Sell, sell: Asset { amount: TokenAmount(1000000000000000000), token: TokenAddress(ContractAddress(0x5fbdb2315678afecb367f032d93f642f64180aa3)) }, buy: Asset { amount: TokenAmount(1), token: TokenAddress(ContractAddress(0x68b1d87f95878fe05b998f19b66f4baba5de1aed)) }, executed_sell: TokenAmount(1000000000000000000), executed_buy: TokenAmount(995832968112110442234) }}, prices: {TokenAddress(ContractAddress(0x5fbdb2315678afecb367f032d93f642f64180aa3)): TokenAmount(995832968112110442234), TokenAddress(ContractAddress(0x68b1d87f95878fe05b998f19b66f4baba5de1aed)): TokenAmount(999825289449667218)}, gas: Some(Gas(337199)) }
    2025-12-09T09:59:43.651Z DEBUG auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}: autopilot::run_loop::observe: proposed solution driver=test_solver orders=[0xa0d50a2cc9c54b694330d7c4d622e07342ba61702e62d24ac9af2b0398b3e825b7f8bc63bbcad18155201308c8f3540b07f84f5effffffff] solution=3
    2025-12-09T09:59:43.651Z  WARN auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}: autopilot::run_loop: picked submission deadline block_deadline=42
    2025-12-09T09:59:43.677Z  WARN auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}: autopilot::run_loop: post-processing completed auction_id=4 time=26.286574ms
    2025-12-09T09:59:43.677Z  INFO auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}: autopilot::run_loop: winner driver=test_solver solution=3
    2025-12-09T09:59:43.678Z  INFO auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}: autopilot::run_loop: settling driver=test_solver solution=3
    2025-12-09T09:59:43.678Z DEBUG auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}:wait_for_settlement_transaction: autopilot::run_loop: waiting for tag current=40 deadline=42 auction_id=4
    2025-12-09T09:59:43.680Z DEBUG /settle{solver="test_solver" auction_id=4}: driver::domain::competition: settle deadline exceeded current_block=45 submission_deadline=42
    2025-12-09T09:59:43.680Z  WARN /settle{solver="test_solver" auction_id=4}: driver::infra::observe: failed to settle err=DeadlineExceeded(DeadlineExceeded)
    2025-12-09T09:59:43.681Z  WARN auction{auction_id=4}:single_run{auction_id=4 auction_block=35 auction_orders=1}: autopilot::run_loop: settlement failed err=Other(bad status 400 Bad Request: {"kind":"DeadlineExceeded","description":"Exceeded solution deadline"}) driver=test_solver

Changes

So far only the driver has been using the new web socket based current_block_stream implementation which has way lower latency than the polling implementation. The fix was to make the orderbook and autopilot also use the ws stream to keep them in sync. With this change the flaky test runner was able to run without issues with even tighter deadlines than before (2 blocks instead of 5).

How to test

Run with flaky test runner

@MartinquaXD MartinquaXD marked this pull request as ready for review December 9, 2025 10:52
@MartinquaXD MartinquaXD requested a review from a team as a code owner December 9, 2025 10:52
@MartinquaXD MartinquaXD enabled auto-merge December 9, 2025 11:47
@MartinquaXD MartinquaXD added this pull request to the merge queue Dec 9, 2025
Merged via the queue into main with commit 810c975 Dec 9, 2025
18 checks passed
@MartinquaXD MartinquaXD deleted the ethflow-flaky-test branch December 9, 2025 12:07
@github-actions github-actions bot locked and limited conversation to collaborators Dec 9, 2025
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants