Commit 810c975
authored
Fix flaky test
# 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](https://github.com/cowprotocol/services/actions/runs/20060234457/job/57535114851?pr=3953)
without issues with even tighter deadlines than before (2 blocks instead
of 5).
## How to test
Run with flaky test runnerlocal_node_eth_flow_without_quote (#3953)1 parent 151479f commit 810c975
1 file changed
+10
-6
lines changed| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
1 | 1 | | |
2 | 2 | | |
3 | | - | |
4 | | - | |
5 | | - | |
6 | | - | |
7 | | - | |
8 | | - | |
| 3 | + | |
| 4 | + | |
| 5 | + | |
| 6 | + | |
| 7 | + | |
| 8 | + | |
| 9 | + | |
| 10 | + | |
| 11 | + | |
9 | 12 | | |
10 | 13 | | |
11 | 14 | | |
| |||
128 | 131 | | |
129 | 132 | | |
130 | 133 | | |
| 134 | + | |
131 | 135 | | |
132 | 136 | | |
133 | 137 | | |
| |||
0 commit comments