Multiple tests fail in CI with "inbound service overloaded" warnings

[arya2]

Motivation

This test is failing in CI on main: https://github.com/ZcashFoundation/zebra/actions/runs/4687263326/jobs/8306335685#step:15:598

Error:
0: stdout of command did not log any matches for the given regex,
within the 3m command timeout

Location:
/Users/runner/work/zebra/zebra/zebra-test/src/command.rs:854

Match Regex:
[
"stopping at configured height",
]

Command:
cd "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/zebrad_testsKJDaJD" && "/Users/runner/work/zebra/zebra/target/release/zebrad" "-c" "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/zebrad_testsKJDaJD/zebrad.toml" "start"

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

0: zebra_test::command::expect_line_matching_regexes with success_regexes=RegexSet(["stopping at configured height"]) stream_name="stdout"
at zebra-test/src/command.rs:810
1: zebra_test::command::expect_stdout_line_matches with success_regex="stopping at configured height"
at zebra-test/src/command.rs:701
2: acceptance::common::sync::check_sync_logs_until with network=Mainnet stop_regex="stopping at configured height" mempool_behavior=ForceActivationAt(Height(0)) check_legacy_chain=true
at zebrad/tests/common/sync.rs:303

Error:
0: stdout of command did not log any matches for the given regex,
within the 3m command timeout

Location:
/opt/zebrad/zebra-test/src/command.rs:854

Match Regex:
[
"stopping at configured height",
]

Command:
cd "/tmp/zebrad_testsnttLId" && "/opt/zebrad/target/release/zebrad" "-c" "/tmp/zebrad_testsnttLId/zebrad.toml" "start"

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

0: zebra_test::command::expect_line_matching_regexes with success_regexes=RegexSet(["stopping at configured height"]) stream_name="stdout"
at zebra-test/src/command.rs:810
1: zebra_test::command::expect_stdout_line_matches with success_regex="stopping at configured height"
at zebra-test/src/command.rs:701
2: acceptance::common::sync::check_sync_logs_until with network=Mainnet stop_regex="stopping at configured height" mempool_behavior=ForceActivationAt(Height(0)) check_legacy_chain=true
at zebrad/tests/common/sync.rs:303
3: acceptance::common::sync::sync_until with height=Height(400) network=Mainnet stop_regex="stopping at configured height" timeout=180s mempool_behavior=ForceActivationAt(Height(0)) checkpoint_sync=true check_legacy_chain=true
at zebrad/tests/common/sync.rs:182

It also failed in 'CI Docker / Test all' in a dependabot PR: https://github.com/ZcashFoundation/zebra/actions/runs/4691947659/jobs/8317961127?pr=6505#step:3:3777

Error:
0: stdout of command did not log any matches for the given regex,
within the 3m command timeout

Location:
/opt/zebrad/zebra-test/src/command.rs:854

Match Regex:
[
"stopping at configured height",
]

Command:
cd "/tmp/zebrad_testsnttLId" && "/opt/zebrad/target/release/zebrad" "-c" "/tmp/zebrad_testsnttLId/zebrad.toml" "start"

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

0: zebra_test::command::expect_line_matching_regexes with success_regexes=RegexSet(["stopping at configured height"]) stream_name="stdout"
at zebra-test/src/command.rs:810
1: zebra_test::command::expect_stdout_line_matches with success_regex="stopping at configured height"
at zebra-test/src/command.rs:701
2: acceptance::common::sync::check_sync_logs_until with network=Mainnet stop_regex="stopping at configured height" mempool_behavior=ForceActivationAt(Height(0)) check_legacy_chain=true
at zebrad/tests/common/sync.rs:303
3: acceptance::common::sync::sync_until with height=Height(400) network=Mainnet stop_regex="stopping at configured height" timeout=180s mempool_behavior=ForceActivationAt(Height(0)) checkpoint_sync=true check_legacy_chain=true
at zebrad/tests/common/sync.rs:182

[arya2]

Medium priority because it's happened twice in ~10 hours.

[teor2345]

This could be a temporary failure caused by a network scanner, or by load on the Zcash network.

PR #6235 modifies the mempool, but that code is off by default.
PR #6357 changes some network configs via GitHub variables, but it should be a refactor.

I can't see anything else that's recent that could be related.

[teor2345]

Another mempool test failed in PR #6486, with what appears to be a timing issue components::mempool::storage::tests::prop::eviction_list_time_mixed:

Message: Test failed: assertion failed: e.contains_key(&txid.mined_id()) at zebrad/src/components/mempool/storage/tests/prop.rs:1124; minimal failing input: mut rejection_template = Legacy(transaction::Hash("966cb0ddd6f9dd0a3e556c9d1a11bd83af71e97707602b62b5580aae1885cbf0"))

https://github.com/ZcashFoundation/zebra/actions/runs/4689185170/jobs/8310620107?pr=6486#step:14:3624

It's possible that a recent dependency update or compiler update changed Zebra's performance or execution order, and we need to fix some tests to make them more robust.

[teor2345]

Failed PR #6512 in the merge queue:
https://github.com/ZcashFoundation/zebra/actions/runs/4695724862/jobs/8325176193#step:3:3989

@mpguerra another test we should fix, the overall error rate is stopping us merging PRs.

[teor2345]

Unfortunately this fix wasn't enough, PR #6534 failed with this error:
https://github.com/ZcashFoundation/zebra/actions/runs/4727807392/jobs/8389174832?pr=6534#step:3:14012

[teor2345]

It looks like the syncer just hangs after downloading the genesis block:

2023-04-18T03:00:01.981444Z INFO {net="Main"}: zebrad::components::sync::progress: estimated progress to chain tip sync_percent=0.000% current_height=Height(0) network_upgrade=Genesis remaining_sync_blocks=2068339 time_since_last_state_block=5s
2023-04-18T03:01:01.981427Z INFO {net="Main"}: zebrad::components::sync::progress: estimated progress to chain tip sync_percent=0.000% current_height=Height(0) network_upgrade=Genesis remaining_sync_blocks=2068340 time_since_last_state_block=1m 5s

https://github.com/ZcashFoundation/zebra/actions/runs/4727807392/jobs/8389174832?pr=6534#step:3:13977

What should be happening is the syncer downloading the next checkpoint, and exiting once block 1 is committed to the state.

[teor2345]

I'm starting to wonder if this revert was incorrect:

• Revert "Ignore Firo non-Zcash nodes in Zebra's address book (https://github.com/ZcashFoundation/zebra/pull/6398[)"](https://github.com/ZcashFoundation/zebra/commit/3d11a09f28aa12f56e089c7e3dc2e26f983c59bf)

I'm going to log the user-agents of the overloaded nodes in #6537, and see if that helps.

[teor2345]

@mpguerra the next step in solving this issue is merging PR #6537. Either it will fix the issue, or it will give us diagnostics that help with the fix.

@oxarbitrage has been auto-assigned as the reviewer.

[teor2345]

Failed on the main branch:
https://github.com/ZcashFoundation/zebra/actions/runs/4758889745/jobs/8457510197#step:14:3886

[teor2345]

Failed in PR #6516:
https://github.com/ZcashFoundation/zebra/actions/runs/4759979850/jobs/8459804792?pr=6516#step:15:519

[mpguerra]

@teor2345 can you please add a size for this issue?

[teor2345]

This is still happening, but it's much less frequent. It seems like a state, verifier, or network hang:

2023-04-27T23:37:14.576426Z INFO {net="Main"}: zebrad::components::sync::progress: estimated progress to chain tip sync_percent=0.000% current_height=Height(0) network_upgrade=Genesis remaining_sync_blocks=2079696 time_since_last_state_block=5s
2023-04-27T23:38:14.576409Z INFO {net="Main"}: zebrad::components::sync::progress: estimated progress to chain tip sync_percent=0.000% current_height=Height(0) network_upgrade=Genesis remaining_sync_blocks=2079697 time_since_last_state_block=1m 5s

https://github.com/ZcashFoundation/zebra/actions/runs/4824819949/jobs/8595587969?pr=6581#step:3:4060

I think the next step would be adding some progress logs, just before the first big checkpoint is verified, to find out which part of Zebra is hanging.

It doesn't seem like it is recovering at all, even after a syncer restart. So it is probably the inbound service or something it depends on (the address book, verifiers, or state).

[teor2345]

I'm going to un-assign myself and mark this fix as optional, because it doesn't seem to be happening very often any more.

[teor2345]

Looking at this failure output, it seems like there are a lot of duplicate block and transaction broadcasts.

We could check why the inbound service is performing poorly, or we could combine duplicate inbound requests. But first I want to make sure the inbound service is actually getting time to run after every request is queued.

Show details of inbound block and transaction broadcasts

2023-05-15T15:49:35.023057Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3879
2023-05-15T15:49:35.023250Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/Zebra:1.0.0-rc.4/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=0 connection_state=AwaitingRequest
3880
2023-05-15T15:49:35.023371Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3881
2023-05-15T15:49:35.023443Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3882
2023-05-15T15:49:35.023518Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3883
2023-05-15T15:49:35.023593Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.1/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3884
2023-05-15T15:49:35.023706Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3885
2023-05-15T15:49:35.023831Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3886
2023-05-15T15:49:35.023908Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3887
2023-05-15T15:49:35.023978Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="tx"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::PushTransaction") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3888
2023-05-15T15:49:35.026826Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3889
2023-05-15T15:49:35.026993Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3890
2023-05-15T15:49:35.027284Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3891
2023-05-15T15:49:35.027395Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3892
2023-05-15T15:49:35.027500Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3893
2023-05-15T15:49:35.027659Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3894
2023-05-15T15:49:35.027783Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=0 connection_state=AwaitingRequest
3895
2023-05-15T15:49:35.027903Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3896
2023-05-15T15:49:35.028007Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseTransactionIds") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3897
2023-05-15T15:49:35.028180Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3898
2023-05-15T15:49:35.028308Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.3.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3899
2023-05-15T15:49:35.028413Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3900
2023-05-15T15:49:35.028533Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3901
2023-05-15T15:49:35.028642Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3902
2023-05-15T15:49:35.028743Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3903
2023-05-15T15:49:35.028874Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.5.0/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087054) cached_addrs=1 connection_state=AwaitingRequest
3904
2023-05-15T15:49:35.029012Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest
3905
2023-05-15T15:49:35.029128Z INFO {net="Main"}:{peer=Out("v4redacted:8233")}:msg_as_req{msg="inv"}: zebra_network::peer::connection: inbound service is overloaded, closing connection remote_user_agent="/MagicBean:5.4.2/" negotiated_version=Version(170100) peer="v4redacted:8233" last_peer_state=Some("AwaitingRequest::In::Req::AdvertiseBlock") remote_height=Height(2087053) cached_addrs=1 connection_state=AwaitingRequest

https://github.com/ZcashFoundation/zebra/actions/runs/4981296666/jobs/8916500733#step:3:3906

[teor2345]

From PR #6665:

Another unrelated test failure:

ZcashFoundation/zebra/actions/runs/4993544630/jobs/8942826854#step:14:3930

This seems to be a peer failure, but maybe "all ready peers are missing inventory" shouldn't hang for 4 minutes before trying again.

It's not the same as this bug, but it could be related to it.

[teor2345]

This seems to have stopped happening after our recent fixes.