staking-miner integration tests failed against latest polkadot build.

[github-actions]

Go to https://gitlab.parity.io/parity/mirrors/staking-miner-v2/-/pipelines/251999 to see details about the failure.

[niklasad1]

I did some investigation and it turns out that paritytech/polkadot#6762 broke things for us.

For some reason the trimming stuff from the EPM pallet comes up with active_voters == 0 which in turn comes with faulty weights when those are queried through the runtime API to fetch the weight.

I have some assumptions in the code where for instance voters >= desired_targets but when active_voters == 0 that breaks that as well (see logs below there you can see that trimming occurs)

main branch

➜  staking-miner git:(main) ✗ ./target/debug/staking-miner --uri ws://localhost:9944 monitor --seed-or-path //Alice --dry-run --listen finalized seq-phragmen
2023-03-06T15:14:53.829368Z  WARN staking-miner: failed to connect to client due to Transport(Error when opening the TCP socket: Connection refused (os error 111)), retrying soon..
2023-03-06T15:14:56.331550Z  WARN staking-miner: failed to connect to client due to Transport(Error when opening the TCP socket: Connection refused (os error 111)), retrying soon..
2023-03-06T15:14:58.977365Z  INFO staking-miner: Started prometheus endpoint on http://0.0.0.0:9999
2023-03-06T15:14:58.977399Z  INFO staking-miner: Connected to chain: polkadot
2023-03-06T15:14:59.049640Z  INFO staking-miner: Loaded account Id(AccountId32([212, 53, 147, 199, 21, 253, 211, 28, 97, 20, 26, 189, 4, 169, 159, 214, 130, 44, 133, 88, 133, 76, 205, 227, 154, 86, 132, 231, 165, 109, 162, 125])), AccountInfo { nonce: 0, consumers: 0, providers: 1, sufficients: 0, data: AccountData { free: 10000000000000000, reserved: 0, misc_frozen: 0, fee_frozen: 0 } }
2023-03-06T15:14:59.098829Z  WARN staking-miner: upgrade to version: 9370 failed: SameVersion
thread 'tokio-runtime-worker' panicked at 'assertion failed: voters >= desired_targets as u32', src/epm.rs:282:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

dev branch with some hacks

➜  staking-miner git:(na-debug-weights) ✗ ./target/debug/staking-miner --uri ws://localhost:9944 monitor --seed-or-path //Alice --dry-run --listen finalized seq-phragmen
2023-03-06T15:38:49.042019Z DEBUG staking-miner: attempting to connect to "ws://localhost:9944"
2023-03-06T15:38:49.134230Z  INFO staking-miner: Started prometheus endpoint on http://0.0.0.0:9999
2023-03-06T15:38:49.134256Z  INFO staking-miner: Connected to chain: polkadot
2023-03-06T15:38:49.134310Z TRACE staking-miner: updating metadata constant `ElectionProviderMultiPhase::SignedMaxWeight`: 1471776990000
2023-03-06T15:38:49.134319Z TRACE staking-miner: updating metadata constant `ElectionProviderMultiPhase::MinerMaxLength`: 3538944
2023-03-06T15:38:49.134326Z TRACE staking-miner: updating metadata constant `ElectionProviderMultiPhase::MinerMaxVotesPerVoter`: 16
2023-03-06T15:38:49.209317Z  INFO staking-miner: Loaded account Id(AccountId32([212, 53, 147, 199, 21, 253, 211, 28, 97, 20, 26, 189, 4, 169, 159, 214, 130, 44, 133, 88, 133, 76, 205, 227, 154, 86, 132, 231, 165, 109, 162, 125])), AccountInfo { nonce: 3, consumers: 0, providers: 1, sufficients: 0, data: AccountData { free: 9998799308172092, reserved: 0, misc_frozen: 0, fee_frozen: 0 } }
2023-03-06T15:38:49.210735Z TRACE staking-miner: new event at #236 (0xddc670205cd4e48585453671de791524e6127431d1f036d683ee073de2c6c2e4)
2023-03-06T15:38:49.212290Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 236
2023-03-06T15:38:49.245253Z  WARN staking-miner: upgrade to version: 9370 failed: SameVersion
2023-03-06T15:38:50.295207Z TRACE staking-miner: new event at #237 (0x0db1ff1531845223ff40ed685fff099cbfa6384692dcf643e1b275c28a9e62f0)
2023-03-06T15:38:50.296987Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 237
2023-03-06T15:38:58.303340Z TRACE staking-miner: new event at #238 (0x158cfd3bd586ea06b234c25a40577478cef700dae487d1e9f0638d663f6963e0)
2023-03-06T15:38:58.305901Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 238
2023-03-06T15:39:02.307159Z TRACE staking-miner: new event at #239 (0x62d737cb06f3c51a8cb67dc51bd32d5c14748e9569ad4701cf4ba117b694b09c)
2023-03-06T15:39:02.309611Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 239
2023-03-06T15:39:10.315295Z TRACE staking-miner: new event at #240 (0x47dbe004cec7310f555a7c10ce129b5de7ca0655f04e952dfb97874d4352076f)
2023-03-06T15:39:10.318146Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 240
2023-03-06T15:39:14.320716Z TRACE staking-miner: new event at #241 (0x7b539a845d899d9c6ca8bb5e5234cc31e27b8332ac1f6a17b3d5a9565000877b)
2023-03-06T15:39:14.328131Z  INFO staking-miner: voters=[(AccountId32([190, 93, 219, 21, 121, 183, 46, 132, 82, 79, 194, 158, 120, 96, 158, 60, 175, 66, 232, 90, 161, 24, 235, 254, 11, 10, 212, 4, 181, 189, 210, 95]), 1000000000000, BoundedVec([AccountId32([190, 93, 219, 21, 121, 183, 46, 132, 82, 79, 194, 158, 120, 96, 158, 60, 175, 66, 232, 90, 161, 24, 235, 254, 11, 10, 212, 4, 181, 189, 210, 95])], 16))], desired_targets=1
2023-03-06T15:39:14.328659Z TRACE staking-miner: voters=1, targets=1, active_voters=1, desired_targets=1
2023-03-06T15:39:14.328697Z TRACE staking-miner: Solution with voters=1, desired_targets=1
2023-03-06T15:39:14.330681Z TRACE staking-miner: Received weight of `Solution Extrinsic` from remote node: Weight { ref_time: 5037560276, proof_size: 9317 }
2023-03-06T15:39:14.330719Z TRACE staking-miner: voters=1, targets=1, active_voters=1, desired_targets=1
2023-03-06T15:39:14.330735Z TRACE staking-miner: Solution with voters=1, desired_targets=1
2023-03-06T15:39:14.331734Z TRACE staking-miner: Received weight of `Solution Extrinsic` from remote node: Weight { ref_time: 5037560276, proof_size: 9317 }
2023-03-06T15:39:14.331752Z TRACE staking-miner: voters=1, targets=1, active_voters=0, desired_targets=1
thread 'tokio-runtime-worker' panicked at 'weight_with(0) <= Weight(ref_time: 1471776990000, proof_size: 0)', /home/niklasad1/.cargo/git/checkouts/substrate-7e08433d4c370a21/c408123/frame/election-provider-multi-phase/src/unsigned.rs:684:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
2023-03-06T15:39:14.331941Z  INFO staking-miner: round of execution finished. outcome = Err(Other("JoinError::Panic(Id(42), ...)"))
Error: Other("JoinError::Panic(Id(42), ...)")

dev branch --release with some hacks

➜  staking-miner git:(na-debug-weights) ✗ ./target/release/staking-miner --uri ws://localhost:9944 monitor --seed-or-path //Alice --dry-run --listen finalized seq-phragmen
2023-03-06T15:35:04.761669Z DEBUG staking-miner: attempting to connect to "ws://localhost:9944"
2023-03-06T15:35:04.816776Z  INFO staking-miner: Started prometheus endpoint on http://0.0.0.0:9999
2023-03-06T15:35:04.816797Z  INFO staking-miner: Connected to chain: polkadot
2023-03-06T15:35:04.816813Z TRACE staking-miner: updating metadata constant `ElectionProviderMultiPhase::SignedMaxWeight`: 1471776990000
2023-03-06T15:35:04.816815Z TRACE staking-miner: updating metadata constant `ElectionProviderMultiPhase::MinerMaxLength`: 3538944
2023-03-06T15:35:04.816817Z TRACE staking-miner: updating metadata constant `ElectionProviderMultiPhase::MinerMaxVotesPerVoter`: 16
2023-03-06T15:35:04.819262Z  INFO staking-miner: Loaded account Id(AccountId32([212, 53, 147, 199, 21, 253, 211, 28, 97, 20, 26, 189, 4, 169, 159, 214, 130, 44, 133, 88, 133, 76, 205, 227, 154, 86, 132, 231, 165, 109, 162, 125])), AccountInfo { nonce: 1, consumers: 0, providers: 1, sufficients: 0, data: AccountData { free: 9999599769375709, reserved: 0, misc_frozen: 0, fee_frozen: 0 } }
2023-03-06T15:35:04.819837Z TRACE staking-miner: new event at #198 (0x02faec4fa0c44015b0468db7cd464ca381ecc55ba1f4d67980d899a36da858a2)
2023-03-06T15:35:04.820688Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 198
2023-03-06T15:35:04.860896Z  WARN staking-miner: upgrade to version: 9370 failed: SameVersion
2023-03-06T15:35:06.062437Z TRACE staking-miner: new event at #199 (0xd5a3a09274e97ca8c960f7a375a9ac1ff402a3e8f740edbbd3d1bd898aba3dbf)
2023-03-06T15:35:06.064392Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 199
2023-03-06T15:35:10.066244Z TRACE staking-miner: new event at #200 (0x495586efb8a2cacf0f0634a4afaea81c1dc7493953eebb4fca29c0145944e856)
2023-03-06T15:35:10.068375Z DEBUG staking-miner: ensure_signed_phase failed: IncorrectPhase; skipping block: 200
2023-03-06T15:35:14.070987Z TRACE staking-miner: new event at #201 (0x75b11c091a8c4d06898b118ac8b89d505a06edcdd21fdf030f1ec90839a716f4)
2023-03-06T15:35:14.076446Z  INFO staking-miner: voters=[(AccountId32([190, 93, 219, 21, 121, 183, 46, 132, 82, 79, 194, 158, 120, 96, 158, 60, 175, 66, 232, 90, 161, 24, 235, 254, 11, 10, 212, 4, 181, 189, 210, 95]), 1000000000000, BoundedVec([AccountId32([190, 93, 219, 21, 121, 183, 46, 132, 82, 79, 194, 158, 120, 96, 158, 60, 175, 66, 232, 90, 161, 24, 235, 254, 11, 10, 212, 4, 181, 189, 210, 95])], 16))], desired_targets=1
2023-03-06T15:35:14.076645Z TRACE staking-miner: voters=1, targets=1, active_voters=1, desired_targets=1
2023-03-06T15:35:14.076661Z TRACE staking-miner: Solution with voters=1, desired_targets=1
2023-03-06T15:35:14.077531Z TRACE staking-miner: Received weight of `Solution Extrinsic` from remote node: Weight { ref_time: 5037560276, proof_size: 9317 }
2023-03-06T15:35:14.077541Z TRACE staking-miner: voters=1, targets=1, active_voters=1, desired_targets=1
2023-03-06T15:35:14.077546Z TRACE staking-miner: Solution with voters=1, desired_targets=1
2023-03-06T15:35:14.078308Z TRACE staking-miner: Received weight of `Solution Extrinsic` from remote node: Weight { ref_time: 5037560276, proof_size: 9317 }
2023-03-06T15:35:14.078312Z DEBUG runtime::election-provider: 🗳 from 1 assignments, truncating to 0 for weight, removing 1
2023-03-06T15:35:14.078332Z TRACE staking-miner: voters=1, targets=1, active_voters=0, desired_targets=0
2023-03-06T15:35:14.078343Z  INFO staking-miner: Mined solution with ElectionScore { minimal_stake: 340282366920938463463374607431768211455, sum_stake: 0, sum_stake_squared: 0 } size: SolutionOrSnapshotSize { voters: 1, targets: 1 } round: 11 at: 201, took: 2 ms, len: 16, weight = Weight { ref_time: 18446744073709551615, proof_size: 18446744073709551615 }
2023-03-06T15:35:14.079510Z DEBUG staking-miner: submitted solutions: []
2023-03-06T15:35:14.079520Z TRACE staking-miner: Solution validity verification took: 0 ms
2023-03-06T15:35:14.079623Z DEBUG subxt::tx::tx_client: tx additional_and_extra_params: BaseExtrinsicParams { era: Immortal, nonce: 1, tip: PlainTip { tip: 0 }, spec_version: 9370, transaction_version: 20, genesis_hash: 0xc2c516fb4c6edacf4878d50cdfe4d71606b29ca6233e561735425118cf4dc1e4, mortality_checkpoint: 0xc2c516fb4c6edacf4878d50cdfe4d71606b29ca6233e561735425118cf4dc1e4, marker: PhantomData<subxt::config::substrate::SubstrateConfig> }
2023-03-06T15:35:14.079670Z DEBUG subxt::tx::tx_client: tx signature: 019cddb2fe8a8eba3e730fe6ba3757a3e973b342327175ff4d2f9d3a7245432a672ad9d4aec6a942defc7a7d547ec5b0816dc92bb23e7d3d1e67427ff635aaab88
2023-03-06T15:35:18.036265Z DEBUG subxt::events::events_type: Decoding Event 'System::ExtrinsicSuccess'
2023-03-06T15:35:18.036289Z DEBUG subxt::events::events_type: Decoding Event 'System::ExtrinsicSuccess'
2023-03-06T15:35:18.036295Z DEBUG subxt::events::events_type: Decoding Event 'Balances::Withdraw'
2023-03-06T15:35:18.036304Z DEBUG subxt::events::events_type: Decoding Event 'Balances::Reserved'
2023-03-06T15:35:18.036310Z DEBUG subxt::events::events_type: Decoding Event 'ElectionProviderMultiPhase::SolutionStored'
2023-03-06T15:35:18.036320Z  INFO staking-miner: Included at 0x382fa62b257cf38ec1b853bb37c690a44c487c0a9a2fdbe3f4ad205ee421ec2a
^A[2023-03-06T15:35:22.081228Z TRACE staking-miner: new event at #202 (0x200803882fc3b7a34dffb24f34820a75cee4d57f13e6b8b07eea68b530fc64ef)

The question is really whether this a bug in polkadot or "wrong assumptions in the repo", I could probably "workaround" this such as provide max weight/min weight but I'm confused and not really follow why the trimming stuff occurs by the weight stuff in that PR.

//cc @kianenigma @gpestana