Handle duplicate block errors

[teor2345]

Version

zebrad main with all outstanding workaround PRs applied, including #1370 and #1371.

Description

As Zebra sync approaches the tip, it starts encountering duplicate block errors:

• sync: zebrad::components::sync: error extending tips: duplicate hash queued for download
• error downloading and verifying block: AlreadyInChain

Once these errors pass, the syncer gets into a loop where it has exhausted prospective tips. It seems to lag 10-100 blocks behind the current chain tip. It's unclear why short block locator requests and responses don't work.

Suggested Solutions

• make sync and inbound check if a block hash is in any chain or any queue (Make sync, inbound, and block verifier check if a block hash is in any chain or any queue #862)
  • currently, the syncer and inbound only check for best chain blocks, which is incorrect
• make sync and inbound share the same download and verify list, or check each others' lists
  • also check the checkpoint verifier queue
  • also check the non-finalized and finalized state queues
• analyse and fix the errors and warnings, because they impact user experience
  • partly fixed by Ignore AlreadyInChain error in the syncer #2890
• look into the sync lag issue if it impacts gossiped block downloads Investigate sync slowness near the chain tip #2877
• document expected sync behaviour as part of our alpha release notes docs: update readme #1118
• reduce spurious bug reports Disable issue URLs for "duplicate hash" errors #1517

Detailed Logs

When the Zcash Mainnet tip was around 1053180:

Nov 24 20:57:25.888  INFO sync:obtain_tips:state: zebra_state::service::non_finalized_state::chain: adding block to chain block=Block { height: Height(1052830), hash: 00000000021ca3819a3cd04b
772ed884b5511d63e1aa861e0c2174fdced1b057 }                                                                                                                                                     
Nov 24 20:57:25.888  INFO sync:obtain_tips:state: zebra_state::service::non_finalized_state::chain: adding block to chain block=Block { height: Height(1052831), hash: 0000000000499659e92d0783
407b10151ef21039bd5da26891ee8773ae808790 }                                                                                                                                                     
Nov 24 20:57:31.989  WARN sync: zebrad::components::sync: error extending tips e=                                                                                                              
   0: duplicate hash queued for download                                                                                                                                                       
                                                                                                                                                                                               
Location:                                                                                                                                                                                      
   zebrad/src/components/sync/downloads.rs:116                                                                                                                                                 
                                                                                                                                                                                               
  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━                                                                                                             
                                                                                                                                                                                               
   0: zebrad::components::sync::extend_tips                                                                                                                                                    
      at zebrad/src/components/sync.rs:381                                                                                                                                                     
   1: zebrad::components::sync::sync
      at zebrad/src/components/sync.rs:150

Nov 24 20:58:20.516  INFO sync: zebrad::components::sync: extending tips tips.len=1 in_flight=220 lookahead_limit=2000
Nov 24 20:58:20.846  WARN sync: zebrad::components::sync: error downloading and verifying block e=Block(Block { source: AlreadyInChain(block::Hash("000000000089829288a6804c88ab4bf324969d378f8
41d6ddc8e2ba422cd049c"), 37) })
Nov 24 20:58:20.846  INFO sync: zebrad::components::sync: waiting to restart sync timeout=45s
Nov 24 20:59:05.847  INFO sync: zebrad::components::sync: starting sync, obtaining new tips
Nov 24 20:59:05.847  INFO sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(1053177) min_locator_height=1053078 locators=[Height(1053177), Height(1053176), He
ight(1053175), Height(1053173), Height(1053169), Height(1053161), Height(1053145), Height(1053113), Height(1053078)]
Nov 24 20:59:11.848  INFO sync: zebrad::components::sync: exhausted prospective tip set
Nov 24 20:59:11.848  INFO sync: zebrad::components::sync: waiting to restart sync timeout=45s

When the Zcash Mainnet tip was around 1053200:

Nov 24 21:12:41.647  INFO sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(1053185) min_locator_height=1053086 locators=[Height(1053185), Height(1053184), He
ight(1053183), Height(1053181), Height(1053177), Height(1053169), Height(1053153), Height(1053121), Height(1053086)]                                                                           
Nov 24 21:12:47.648  INFO sync: zebrad::components::sync: extending tips tips.len=1 in_flight=9 lookahead_limit=2000
Nov 24 21:12:47.878  INFO sync:obtain_tips:state: zebra_state::service::non_finalized_state::chain: adding block to chain block=Block { height: Height(1053186), hash: 000000000046711304c83bab
e675a6926db35256edd6923830d1f721f81907d4 }
Nov 24 21:12:50.468  INFO sync: zebrad::components::sync: exhausted prospective tip set
Nov 24 21:12:50.468  INFO sync: zebrad::components::sync: waiting to restart sync timeout=45s
Nov 24 21:13:35.469  INFO sync: zebrad::components::sync: starting sync, obtaining new tips

[hdevalence]

We should wait to examine this until after implementing block gossip (#1082, #1328), since the sync component is only supposed to be responsible for initial block sync, not ongoing gossip-based sync. So the sync component exhausting tips and restarting isn't in itself a problem. But this behavior doesn't sound good, and should be investigated:

It seems to lag 10-100 blocks behind the current chain tip. It's unclear why short block locator requests and responses don't work.

[teor2345]

I'm not seeing these errors on Mainnet any more.

We should re-test to make sure they're not happening.

[oxarbitrage]

With current main branch in the Mainnet i got this error however the sync is still going after it:

Dec 01 13:40:00.469  INFO sync:obtain_tips: zebra_state::service: pruned utxo requests old_len=1071 new_len=64 prune_count=1007 tip=Some((Height(582679), block::Hash("0000000001910df5dc7650d8e6ff9a9ad9195c9e4d85ad45db525cfec112378c")))
Dec 01 13:40:00.469  INFO sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(582679) min_locator_height=582580 locators=[Height(582679), Height(582678), Height(582677), Height(582675), Height(582671), Height(582663), Height(582647), Height(582615), Height(582580)]
Dec 01 13:40:07.923  INFO sync: zebrad::components::sync: extending tips tips.len=3 in_flight=61 lookahead_limit=2000
Dec 01 13:40:20.290  WARN sync: zebrad::components::sync: error extending tips e=
   0: duplicate hash queued for download

Location:
   zebrad/src/components/sync/downloads.rs:116

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
  
   0: zebrad::components::sync::extend_tips
      at zebrad/src/components/sync.rs:381
   1: zebrad::components::sync::sync
      at zebrad/src/components/sync.rs:150

Backtrace omitted.
Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.

Consider reporting this error using this URL: https://github.com/ZcashFoundation/zebra/issues/new?title=%3Cautogenerated-issue%3E&body=%23%23+Error%0A%60%60%60%0AError%3A+%0A+++0%3A+duplicate+hash+queued+for+download%0A%60%60%60%0A%0A%23%23+Metadata%0A%7Ckey%7Cvalue%7C%0A%7C--%7C--%7C%0A%7C**version**%7C3.0.0-alpha.0%7C%0A%0A%0A%23%23+SpanTrace%0A%0A%3Cdetails%3E%0A%0A%60%60%60%0ASpanTrace%3A%0A+++0%3A+zebrad%3A%3Acomponents%3A%3Async%3A%3Aextend_tips%0A+++++++++++++at+zebrad%2Fsrc%2Fcomponents%2Fsync.rs%3A381%0A+++1%3A+zebrad%3A%3Acomponents%3A%3Async%3A%3Async%0A+++++++++++++at+zebrad%2Fsrc%2Fcomponents%2Fsync.rs%3A150%0A%60%60%60%0A%3C%2Fdetails%3E
Dec 01 13:40:20.292  INFO sync: zebrad::components::sync: waiting to restart sync timeout=45s
Dec 01 13:41:05.293  INFO sync: zebrad::components::sync: starting sync, obtaining new tips
Dec 01 13:41:05.294  INFO sync:obtain_tips: zebra_state::service: pruned utxo requests old_len=1231 new_len=51 prune_count=1180 tip=Some((Height(582684), block::Hash("0000000000b69bc96affdc5da5e7d995a114ffc6032410b00e309a6ae47a579b")))
Dec 01 13:41:05.294  INFO sync:obtain_tips:state: zebra_state::util: created block locator tip_height=Height(582684) min_locator_height=582585 locators=[Height(582684), Height(582683), Height(582682), Height(582680), Height(582676), Height(582668), Height(582652), Height(582620), Height(582585)]

[teor2345]

I'm seeing these errors a long way from the tip on testnet.

[teor2345]

We might want to remove the spantrace - it makes the error seem much more serious than it actually is.

[yaahc]

We might want to remove the spantrace - it makes the error seem much more serious than it actually is.

I can look into hiding it in the logs but I don't think we should get rid of it. I'm thinking maybe just don't show it in logs by default but always include it in the generated issue url.

Also it might be useful to drop the level on this span so that it gets included in the spantrace

    #[instrument(level = "debug", skip(self), fields(%hash))]
    pub async fn download_and_verify(&mut self, hash: block::Hash) -> Result<(), Report> {
        if self.cancel_handles.contains_key(&hash) {
            return Err(eyre!("duplicate hash queued for download"));
        }

[teor2345]

We might want to remove the spantrace - it makes the error seem much more serious than it actually is.

I can look into hiding it in the logs but I don't think we should get rid of it. I'm thinking maybe just don't show it in logs by default but always include it in the generated issue url.

We've told users to ignore these errors in the README, so I disabled the issue URL in #1517

Also it might be useful to drop the level on this span so that it gets included in the spantrace

I think an info-level span would be too verbose. Instead, I included the hash in the error message in #1517

[teor2345]

This is fixed or covered by #862