-
Notifications
You must be signed in to change notification settings - Fork 105
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
fix(bug): Reduces Debug
output for Network
on Regtest and default Testnet
#8760
Conversation
Debug
output Network
on Regtest and default Testnet to fix a testDebug
output for Network
on Regtest and default Testnet to fix a test
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Makes sense to me, lets try it out. I added the do not merge
label so it can be removed if/after the full sync pass.
This are the logs from the the VM running the full-sync-test. It's still not stopping: 2024-08-14T12:53:13.846386Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957435) network_upgrade=Nu5 remaining_sync_blocks=1 time_since_last_state_block=1m
2024-08-14T12:53:37.115045Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=000e3ba687fbbc7cb647a61829a40b250c41d0db42f373b5810f90229301a2c7}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957436)
2024-08-14T12:53:47.804474Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=In("v4redacted:41432")
2024-08-14T12:53:47.804480Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=Out("v4redacted:45099")
2024-08-14T12:53:48.798871Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957436))
2024-08-14T12:53:54.801320Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T12:53:54.801339Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957436))
2024-08-14T12:53:57.762701Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="mempool"}:mempool: zebrad::components::mempool: answered mempool request req=TransactionIds res_count=0
2024-08-14T12:54:09.903172Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T12:54:13.858335Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957436) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T12:54:54.181282Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=000a66f01adbe35c4faa7382e7a3eb6293d69071f2d76f2327c8671f8101b0aa}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957437)
2024-08-14T12:55:01.802198Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957437))
2024-08-14T12:55:07.803814Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T12:55:07.803833Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957437))
2024-08-14T12:55:09.903962Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T12:55:13.870383Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957437) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T12:55:24.384050Z INFO zebra_state::service::finalized_state::disk_format::upgrade: checking new blocks were written in current database format running_version=26.0.0
2024-08-14T12:55:24.384073Z INFO zebra_state::service::finalized_state::disk_format::upgrade: checking database format produced by new blocks in this instance is valid running_version=26.0.0
2024-08-14T12:55:24.907050Z INFO zebra_state::service::finalized_state::disk_format::upgrade: database format is valid running_version=26.0.0 inital_disk_version=26.0.0
2024-08-14T12:55:52.838400Z INFO {zebrad="702ae54" net="Test"}:peer_cache_updater: zebra_network::config: updated cached peer IP addresses cached_ip_count=10 peer_cache_file="/root/.cache/zebra/network/testnet.peers"
2024-08-14T12:56:09.904199Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T12:56:13.884578Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957437) network_upgrade=Nu5 remaining_sync_blocks=1 time_since_last_state_block=1m
2024-08-14T12:56:14.804596Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957437))
2024-08-14T12:56:20.805941Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T12:56:20.805957Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957437))
2024-08-14T12:56:55.723616Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=In("v4redacted:36060")
2024-08-14T12:56:55.723620Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=Out("v4redacted:45099")
2024-08-14T12:57:09.903845Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T12:57:13.897723Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957437) network_upgrade=Nu5 remaining_sync_blocks=1 time_since_last_state_block=2m
2024-08-14T12:57:27.806382Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957437))
2024-08-14T12:57:33.808044Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T12:57:33.808061Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957437))
2024-08-14T12:57:45.664875Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=002e73555a0eac157d7156b5282c89dbd6e51f9701e035ebb9fb888c8c9b8fd4}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957438)
2024-08-14T12:58:13.910085Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957438) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T12:58:40.809430Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957438))
2024-08-14T12:58:46.811134Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T12:58:46.811153Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957438))
2024-08-14T12:59:01.051128Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=002def1810069221bc60ab05d0a7f6f3a9d9924ec47299af46b9d364dc2989d5}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957439)
2024-08-14T12:59:09.903119Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T12:59:13.924284Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957439) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T12:59:29.889117Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=001628c6bef09992b342af6b5a6ce6a271a8c2eb8b0009336c90ccaada0d1507}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957440)
2024-08-14T12:59:53.590120Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=0023854cc5b74805c4e39bb8e79b1a9ca93d9c57f30b0eacc93688274bb99069}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957441)
2024-08-14T12:59:53.812323Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957441))
2024-08-14T12:59:58.754242Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=In("v4redacted:59092")
2024-08-14T12:59:58.754246Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=Out("v4redacted:45099")
2024-08-14T12:59:59.813212Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T12:59:59.813233Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957441))
2024-08-14T13:00:09.903965Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T13:00:13.936484Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957441) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T13:00:24.907128Z INFO zebra_state::service::finalized_state::disk_format::upgrade: checking new blocks were written in current database format running_version=26.0.0
2024-08-14T13:00:24.907146Z INFO zebra_state::service::finalized_state::disk_format::upgrade: checking database format produced by new blocks in this instance is valid running_version=26.0.0
2024-08-14T13:00:25.433264Z INFO zebra_state::service::finalized_state::disk_format::upgrade: database format is valid running_version=26.0.0 inital_disk_version=26.0.0
2024-08-14T13:00:32.793112Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=00215317d324f5a34cdb9d832c7ca82a803281fb84501e7e2204355ce25be9e0}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957442)
2024-08-14T13:00:52.839764Z INFO {zebrad="702ae54" net="Test"}:peer_cache_updater: zebra_network::config: updated cached peer IP addresses cached_ip_count=11 peer_cache_file="/root/.cache/zebra/network/testnet.peers"
2024-08-14T13:01:06.814959Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957442))
2024-08-14T13:01:09.903604Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T13:01:12.816308Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T13:01:12.816325Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957442))
2024-08-14T13:01:13.071364Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=003c0972d56ae0c7edfe6f00feef4b090d8abc6334019be77372fcc268724d43}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957443)
2024-08-14T13:01:13.948480Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957443) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T13:01:37.142879Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:18233")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=00147c0e05d8444d3b4cf2a46bcc61baa9431d525b0803776045a0f30330a7d7}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957444)
2024-08-14T13:02:09.903154Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T13:02:13.961754Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957444) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T13:02:19.817272Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957444))
2024-08-14T13:02:25.818705Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T13:02:25.818726Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957444))
2024-08-14T13:02:40.356966Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:30835")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=00350166993128ad6c34d2e79eb70d93020676d1bc72bf5cec400d24e911e5ba}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957445)
2024-08-14T13:03:09.904006Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T13:03:12.905692Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=In("v4redacted:43518")
2024-08-14T13:03:12.905693Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=Out("v4redacted:45099")
2024-08-14T13:03:13.975290Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957445) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T13:03:18.264050Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:30835")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=001b7fbc92b03c5a85044fb153adc4d8f3592e3cdadab699f81ea5072b9d1bb5}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957446)
2024-08-14T13:03:32.819515Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957446))
2024-08-14T13:03:38.820437Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T13:03:38.820455Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957446))
2024-08-14T13:04:09.903365Z INFO {zebrad="702ae54" net="Test"}:crawl_and_dial{new_peer_interval=30s}:crawl{should_always_dial=false}: zebra_network::peer_set::candidate_set: timeout waiting for peer service readiness or peer responses
2024-08-14T13:04:13.989039Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957446) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T13:04:45.821310Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: starting sync, obtaining new tips state_tip=Some(Height(2957446))
2024-08-14T13:04:51.822983Z INFO {zebrad="702ae54" net="Test"}:sync:try_to_sync: zebrad::components::sync: exhausted prospective tip set
2024-08-14T13:04:51.823003Z INFO {zebrad="702ae54" net="Test"}:sync: zebrad::components::sync: waiting to restart sync timeout=67s state_tip=Some(Height(2957446))
2024-08-14T13:05:12.973459Z INFO {zebrad="702ae54" net="Test"}:{peer=Out("v4redacted:30835")}:msg_as_req{msg="inv"}:inbound:download_and_verify{hash=00310957b250b3852235b0ffed22833d866f28ae68f231a815acc0ae698c92c8}: zebrad::components::inbound::downloads: downloaded and verified gossiped block height=Height(2957447)
2024-08-14T13:05:14.000435Z INFO {zebrad="702ae54" net="Test"}: zebrad::components::sync::progress: finished initial sync to chain tip, using gossiped blocks sync_percent=100.000% current_height=Height(2957447) network_upgrade=Nu5 remaining_sync_blocks=0 time_since_last_state_block=0s
2024-08-14T13:05:25.433355Z INFO zebra_state::service::finalized_state::disk_format::upgrade: checking new blocks were written in current database format running_version=26.0.0
2024-08-14T13:05:25.433372Z INFO zebra_state::service::finalized_state::disk_format::upgrade: checking database format produced by new blocks in this instance is valid running_version=26.0.0
2024-08-14T13:05:25.963530Z INFO zebra_state::service::finalized_state::disk_format::upgrade: database format is valid running_version=26.0.0 inital_disk_version=26.0.0
2024-08-14T13:05:34.446206Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=In("v4redacted:39958")
2024-08-14T13:05:34.446212Z INFO zebra_network::peer::handshake: rejecting self-connection attempt connected_addr=Out("v4redacted:45099") |
Debug
output for Network
on Regtest and default Testnet to fix a testDebug
output for Network
on Regtest and default Testnet
Now I'm lost on why the test isn't finishing, I see all of the expected logs, and it's the same code as the full sync Mainnet test except for the expected environment variable and the network being used. I'd like to merge this change anyways since I don't see "network: Testnet," anywhere before "starting legacy chain check" in other testnet full syncs, so I would expect the test to fail without it. |
Motivation
This has likely been part of what was causing our full Testnet sync to fail in CI as the test expects a comma after the network name.
Solution
Debug
output on the default Testnet to just the network nameRelated changes:
Debug
output on Regtest to just the network name and activation heights (since the other fields are not currently configurable)Tests
The
full_sync_testnet
test should pass on this PR, running one here: https://github.com/ZcashFoundation/zebra/actions/runs/10381498189.PR Author's Checklist
PR Reviewer's Checklist