Skip to content
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

Server keeps receiving block headers it already has #373

Closed
yeastplume opened this issue Nov 22, 2017 · 9 comments
Closed

Server keeps receiving block headers it already has #373

yeastplume opened this issue Nov 22, 2017 · 9 comments

Comments

@yeastplume
Copy link
Member

yeastplume commented Nov 22, 2017

Showing up in logs doing a full sync now, processing header 1 through 511 repeatedly on every single block validation.

Nov 22 21:01:42.821 DEBG Processing header 4eea4198 at 509.
Nov 22 21:01:42.821 DEBG Validating block with cuckoo size 16
Nov 22 21:01:42.822 DEBG Processing header 2676a458 at 510.
Nov 22 21:01:42.822 DEBG Validating block with cuckoo size 16
Nov 22 21:01:42.824 DEBG Processing header 7d54f41e at 511.
Nov 22 21:01:42.824 DEBG Validating block with cuckoo size 16
Nov 22 21:01:42.826 INFO Added 208 headers to the header chain.
Nov 22 21:01:42.831 DEBG Received block 2442d1d4 at 304 from network, going to process.
Nov 22 21:01:42.831 DEBG Processing block 2442d1d4 at 304 with 0 inputs and 1 outputs.
Nov 22 21:01:42.831 DEBG Validating block with cuckoo size 16
Nov 22 21:01:42.832 DEBG Starting new sumtree extension.
Nov 22 21:01:42.864 TRCE Hashing with additional data
Nov 22 21:01:42.867 DEBG Block at 304 with hash 2442d1d4 is valid, going to save and append.
Nov 22 21:01:42.867 INFO Updated head to 2442d1d4 at 304.
Nov 22 21:01:42.867 DEBG Committing sumtree extension.
Nov 22 21:01:42.878 DEBG Sumtree extension done.

Looks as if either the syncer keeps requesting the block headers, or someone keeps sending them to us without us asking

@yeastplume yeastplume changed the title 'Received unfit blockheader' ad inifinitum Server keeps receiving block headers it already has Nov 22, 2017
@yeastplume
Copy link
Member Author

Twice now while trying to sync, crapped out in the exact same place with the same PoisonError

Nov 22 22:20:35.677 INFO Received unfit block header 2676a458 at 510: already in store.
Nov 22 22:20:35.677 DEBG Processing header 7d54f41e at 511.
Novthread ' main22' panicked at ' called `Result::unwrap()` on an `Err` value: "PoisonError { inner: .. }"22', /checkout/src/libcore/result.rs::20860
:35.677 INFO Received unfit block header 7d54f41e at 511: already in store.

@yeastplume
Copy link
Member Author

Relevant bit of stack trace from above:

0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace                                                                                                                                                                                                                     
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49                                                                                                                                                                                                     
   1: std::sys_common::backtrace::_print                                                                                                                                                                                                                                        
             at /checkout/src/libstd/sys_common/backtrace.rs:71                                                                                                                                                                                                                 
   2: std::panicking::default_hook::{{closure}}                                                                                                                                                                                                                                 
             at /checkout/src/libstd/sys_common/backtrace.rs:60                                                                                                                                                                                                                 
             at /checkout/src/libstd/panicking.rs:355                                                                                                                                                                                                                           
   3: std::panicking::default_hook                                                                                                                                                                                                                                              
             at /checkout/src/libstd/panicking.rs:371                                                                                                                                                                                                                           
   4: std::panicking::rust_panic_with_hook                                                                                                                                                                                                                                      
             at /checkout/src/libstd/panicking.rs:549                                                                                                                                                                                                                           
   5: std::panicking::begin_panic                                                                                                                                                                                                                                               
             at /checkout/src/libstd/panicking.rs:511                                                                                                                                                                                                                           
   6: std::panicking::begin_panic_fmt                                                                                                                                                                                                                                           
             at /checkout/src/libstd/panicking.rs:495                                                                                                                                                                                                                           
   7: rust_begin_unwind                                                                                                                                                                                                                                                         
             at /checkout/src/libstd/panicking.rs:471                                                                                                                                                                                                                           
   8: core::panicking::panic_fmt                                                                                                                                                                                                                                                
             at /checkout/src/libcore/panicking.rs:69                                                                                                                                                                                                                           
   9: core::result::unwrap_failed                                                                                                                                                                                                                                               
             at /checkout/src/libcore/macros.rs:29                                                                                                                                                                                                                              
  10: <core::result::Result<T, E>>::unwrap                                                                                                                                                                                                                                      
             at /checkout/src/libcore/result.rs:738                                                                                                                                                                                                                             
  11: grin_grin::sync::Syncer::headers_received                                                                                                                                                                                                                                 
             at grin/src/sync.rs:267                                                                                                                                                                                                                                            
  12: <grin_grin::adapters::NetToChainAdapter as grin_p2p::types::NetAdapter>::headers_received                                                                                                                                                                                 
             at grin/src/adapters.rs:144                                                                                                                                                                                                                                        
  13: <grin_p2p::peer::TrackingAdapter as grin_p2p::types::NetAdapter>::headers_received                                                                                                                                                                                        
             at p2p/src/peer.rs:233                                                                                                                                                                                                                                             
  14: grin_p2p::protocol::handle_payload                                                                                                                                                                                                                                        
             at p2p/src/protocol.rs:214                                                                                                                                                                                                                                         
  15: <grin_p2p::protocol::ProtocolV1 as grin_p2p::types::Protocol>::handle::{{closure}}                                                                                                                                                                                        
             at p2p/src/protocol.rs:55                                                                                                                                                                                                                                          
  16: <F as grin_p2p::conn::Handler>::handle                                                                                                                                                                                                                                    
             at p2p/src/conn.rs:66                                                                                                                                                                                                                                              
  17: grin_p2p::conn::TimeoutConnection::listen::{{closure}}                                                                                                                                                                                                                    
             at p2p/src/conn.rs:275                                                                                                                                                                                                                                             
  18: <F as grin_p2p::conn::Handler>::handle                                                                                                                                                                                                                                    
             at p2p/src/conn.rs:66                                                                                                                                                                                                                                              
  19: grin_p2p::conn::Connection::read_msg::{{closure}}::{{closure}}   

@yeastplume
Copy link
Member Author

yeastplume commented Nov 23, 2017

Okay, so digging into this further now, using a fresh sync as an example:

I have nothing, so I create a locator with a single height [0], genesis block, and ask a peer for some blocks. It gives me 512 (the max) back.. 0..511

Nov 23 15:19:58.891 INFO Sync: Starting loop.
Nov 23 15:19:58.892 DEBG Sync: peer 30442690 vs us 1
Nov 23 15:19:58.892 DEBG Sync: blocks to download 0, block downloading 0
Nov 23 15:19:58.892 DEBG Sync: locator heights: [0]
Nov 23 15:19:58.892 DEBG Sync: locator: [e17ea64f]
Nov 23 15:19:58.892 DEBG Sync: Asking peer 91.134.132.74:13414 for more block headers, locator: [e17ea64f]
Nov 23 15:19:58.909 DEBG Received 39 peer addrs, saving.
Nov 23 15:19:59.084 INFO Received 511 block headers
Nov 23 15:19:59.084 DEBG Processing header 254b265f at 1.
Nov 23 15:19:59.084 DEBG Validating block with cuckoo size 16
Nov 23 15:19:59.084 INFO Updated block header head to 254b265f at 1.
Nov 23 15:19:59.085 DEBG Processing header 0e4a33eb at 2.
.
.
Nov 23 15:19:59.886 INFO Updated block header head to 7d54f41e at 511.
Nov 23 15:19:59.886 INFO Added 511 headers to the header chain.

That's all fine.. so now I go off to get the next one:

Nov 23 15:20:00.892 DEBG Sync: peer 30442690 vs us 564463
Nov 23 15:20:00.893 DEBG Sync: blocks to download 511, block downloading 0
Nov 23 15:20:00.893 DEBG Sync: locator heights: [511, 509, 505, 497, 481, 449, 385, 257, 1, 0]
Nov 23 15:20:00.893 DEBG Sync: locator: [e17ea64f]
Nov 23 15:20:00.893 DEBG Sync: Asking peer 91.134.132.74:13414 for more block headers, locator: [e17ea64f]

First, that seems a bit odd that I'm passing the same locator array.. but looking at the heights I only have up to block 255, so I don't have a header higher than 255 the array and can't ask for it (that seems like problem #1). so I've sent the same locator array off and get back (as I'm downloading and processing blocks)

Nov 23 15:20:00.944 DEBG Received block e27edc84 at 4 from network, going to process.
Nov 23 15:20:00.945 DEBG Processing block e27edc84 at 4 with 0 inputs and 1 outputs.
Nov 23 15:20:00.945 DEBG Block e27edc84 refused by chain: Orphan
Nov 23 15:20:00.945 DEBG adapter: notifying syncer: received block e27edc84
Nov 23 15:20:00.951 DEBG Received block 254b265f at 1 from network, going to process.
Nov 23 15:20:00.952 DEBG Processing block 254b265f at 1 with 0 inputs and 1 outputs.
Nov 23 15:20:00.952 DEBG Validating block with cuckoo size 16
Nov 23 15:20:00.954 DEBG Starting new sumtree extension.
Nov 23 15:20:01.031 TRCE Hashing with additional data
Nov 23 15:20:01.032 DEBG Block at 1 with hash 254b265f is valid, going to save and append.
Nov 23 15:20:01.032 INFO Updated head to 254b265f at 1.
Nov 23 15:20:01.032 DEBG Committing sumtree extension.
Nov 23 15:20:01.047 DEBG Sumtree extension done.
Nov 23 15:20:01.047 DEBG Processing block e27edc84 at 4 with 0 inputs and 1 outputs.
Nov 23 15:20:01.047 DEBG adapter: notifying syncer: received block 254b265f
Nov 23 15:20:01.048 DEBG Received block 97ca3e9f at 3 from network, going to process.
Nov 23 15:20:01.048 DEBG Processing block 97ca3e9f at 3 with 0 inputs and 1 outputs.
Nov 23 15:20:01.048 DEBG Block 97ca3e9f refused by chain: Orphan
Nov 23 15:20:01.048 DEBG adapter: notifying syncer: received block 97ca3e9f
Nov 23 15:20:01.049 DEBG Received block afc8c779 at 5 from network, going to process.
Nov 23 15:20:01.049 DEBG Processing block afc8c779 at 5 with 0 inputs and 1 outputs.
Nov 23 15:20:01.049 DEBG Block afc8c779 refused by chain: Orphan
Nov 23 15:20:01.049 DEBG adapter: notifying syncer: received block afc8c779
Nov 23 15:20:01.050 DEBG Received block 0e4a33eb at 2 from network, going to process.
Nov 23 15:20:01.050 DEBG Processing block 0e4a33eb at 2 with 0 inputs and 1 outputs.
Nov 23 15:20:01.050 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.050 DEBG Starting new sumtree extension.
Nov 23 15:20:01.083 TRCE Hashing with additional data
Nov 23 15:20:01.084 DEBG Block at 2 with hash 0e4a33eb is valid, going to save and append.
ov 23 15:20:01.090 DEBG Processing block e27edc84 at 4 with 0 inputs and 1 outputs.
Nov 23 15:20:01.090 DEBG Processing block 97ca3e9f at 3 with 0 inputs and 1 outputs.
Nov 23 15:20:01.090 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.091 DEBG Starting new sumtree extension.
Nov 23 15:20:01.123 TRCE Hashing with additional data
Nov 23 15:20:01.124 DEBG Block at 3 with hash 97ca3e9f is valid, going to save and append.
Nov 23 15:20:01.124 INFO Updated head to 97ca3e9f at 3.
Nov 23 15:20:01.124 DEBG Committing sumtree extension.
Nov 23 15:20:01.129 DEBG Sumtree extension done.
Nov 23 15:20:01.129 DEBG Processing block afc8c779 at 5 with 0 inputs and 1 outputs.
Nov 23 15:20:01.129 DEBG Processing block e27edc84 at 4 with 0 inputs and 1 outputs.
Nov 23 15:20:01.129 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.130 DEBG Starting new sumtree extension.
Nov 23 15:20:01.162 TRCE Hashing with additional data
Nov 23 15:20:01.163 DEBG Block at 4 with hash e27edc84 is valid, going to save and append.
Nov 23 15:20:01.164 INFO Updated head to e27edc84 at 4.
Nov 23 15:20:01.164 DEBG Committing sumtree extension.
Nov 23 15:20:01.169 DEBG Sumtree extension done.
Nov 23 15:20:01.169 DEBG Processing block afc8c779 at 5 with 0 inputs and 1 outputs.
Nov 23 15:20:01.169 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.170 DEBG Starting new sumtree extension.
Nov 23 15:20:01.201 TRCE Hashing with additional data
Nov 23 15:20:01.202 DEBG Block at 5 with hash afc8c779 is valid, going to save and append.
Nov 23 15:20:01.203 INFO Updated head to afc8c779 at 5.
Nov 23 15:20:01.203 DEBG Committing sumtree extension.
Nov 23 15:20:01.208 DEBG Sumtree extension done.
Nov 23 15:20:01.208 DEBG adapter: notifying syncer: received block 0e4a33eb
Nov 23 15:20:01.208 DEBG Received block 8de679c6 at 6 from network, going to process.
Nov 23 15:20:01.208 DEBG Processing block 8de679c6 at 6 with 0 inputs and 1 outputs.
Nov 23 15:20:01.208 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.209 DEBG Starting new sumtree extension.
Nov 23 15:20:01.241 TRCE Hashing with additional data
Nov 23 15:20:01.242 DEBG Block at 6 with hash 8de679c6 is valid, going to save and append.
Nov 23 15:20:01.243 INFO Updated head to 8de679c6 at 6.
Nov 23 15:20:01.243 DEBG Committing sumtree extension.
Nov 23 15:20:01.248 DEBG Sumtree extension done.
Nov 23 15:20:01.248 DEBG adapter: notifying syncer: received block 8de679c6
Nov 23 15:20:01.248 DEBG Received block 56547b24 at 7 from network, going to process.
Nov 23 15:20:01.249 DEBG Processing block 56547b24 at 7 with 0 inputs and 1 outputs.
Nov 23 15:20:01.249 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.250 DEBG Starting new sumtree extension.
Nov 23 15:20:01.282 TRCE Hashing with additional data
Nov 23 15:20:01.284 DEBG Block at 7 with hash 56547b24 is valid, going to save and append.
Nov 23 15:20:01.284 INFO Updated head to 56547b24 at 7.
Nov 23 15:20:01.284 DEBG Committing sumtree extension.
Nov 23 15:20:01.289 DEBG Sumtree extension done.
Nov 23 15:20:01.289 DEBG adapter: notifying syncer: received block 56547b24
Nov 23 15:20:01.290 DEBG Received block 5f6d0b81 at 8 from network, going to process.
Nov 23 15:20:01.290 DEBG Processing block 5f6d0b81 at 8 with 0 inputs and 1 outputs.
Nov 23 15:20:01.290 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.291 DEBG Starting new sumtree extension.
Nov 23 15:20:01.325 TRCE Hashing with additional data
Nov 23 15:20:01.326 DEBG Block at 8 with hash 5f6d0b81 is valid, going to save and append.
Nov 23 15:20:01.327 INFO Updated head to 5f6d0b81 at 8.
Nov 23 15:20:01.327 DEBG Committing sumtree extension.
Nov 23 15:20:01.331 DEBG Sumtree extension done.
Nov 23 15:20:01.331 DEBG adapter: notifying syncer: received block 5f6d0b81
Nov 23 15:20:01.342 INFO Received 511 block headers
Nov 23 15:20:01.331 DEBG adapter: notifying syncer: received block 5f6d0b81
Nov 23 15:20:01.342 INFO Received 511 block headers
Nov 23 15:20:01.342 DEBG Processing header 254b265f at 1.
Nov 23 15:20:01.342 INFO Received unfit block header 254b265f at 1: already in store.
Nov 23 15:20:01.342 DEBG Processing header 0e4a33eb at 2.
Nov 23 15:20:01.343 INFO Received unfit block header 0e4a33eb at 2: already in store.
Nov 23 15:20:01.343 DEBG Processing header 97ca3e9f at 3.
Nov 23 15:20:01.343 INFO Received unfit block header 97ca3e9f at 3: already in store.
Nov 23 15:20:01.343 DEBG Processing header e27edc84 at 4.
Nov 23 15:20:01.344 INFO Received unfit block header e27edc84 at 4: already in store.
Nov 23 15:20:01.344 DEBG Processing header afc8c779 at 5.
Nov 23 15:20:01.344 INFO Received unfit block header afc8c779 at 5: already in store.
Nov 23 15:20:01.344 DEBG Processing header 8de679c6 at 6.
Nov 23 15:20:01.345 INFO Received unfit block header 8de679c6 at 6: already in store.
Nov 23 15:20:01.345 DEBG Processing header 56547b24 at 7.
Nov 23 15:20:01.345 INFO Received unfit block header 56547b24 at 7: already in store.
Nov 23 15:20:01.345 DEBG Processing header 5f6d0b81 at 8.
Nov 23 15:20:01.346 INFO Received unfit block header 5f6d0b81 at 8: already in store.
Nov 23 15:20:01.346 DEBG Processing header 22195b41 at 9.
Nov 23 15:20:01.346 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.347 DEBG Processing header 15638b4e at 10.
Nov 23 15:20:01.347 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.348 DEBG Processing header c6c1478b at 11.
Nov 23 15:20:01.348 DEBG Validating block with cuckoo size 16
Nov 23 15:20:01.349 DEBG Processing header 67d4bac9 at 12.

So we're only seem to be saving the headers in the chain when blocks are actually processed, not when we have the header, which means that we only seem to be able to get a list of headers up to the last block we've actually validated, no higher.

Have to add I don't know if that's intentional, of course, but it doesn't seem quite right.. at best the syncer should stop asking for more headers until it's caught up with processing what it already has

@yeastplume
Copy link
Member Author

yeastplume commented Nov 23, 2017

after letting it run for a while, stop and restart, and it gets a new list of headers, and in this case won't be able to validate anything past block 806, (was was the last header processed)

Nov 23 16:00:31.472 DEBG Sync: blocks to download 28428, block downloading 0
Nov 23 16:00:31.472 DEBG Sync: locator heights: [1139, 1137, 1133, 1125, 1109, 1077, 1013, 885, 629, 117, 0]
Nov 23 16:00:31.473 DEBG Sync: locator: [f240448d, 74767f2c, e17ea64f]
Nov 23 16:00:31.473 DEBG Sync: Asking peer 91.134.132.74:13414 for more block headers, locator: [f240448d, 74767f2c, e17ea64f]
Nov 23 16:00:31.473 DEBG Requesting block 9e0fa8f6 from peer 35.196.208.76:13414.
Nov 23 16:00:31.473 DEBG Requesting block 7d4cc83c from peer 147.75.66.147:13414.
.
.
.
Nov 23 16:00:31.790 DEBG Processing header 128a80e3 at 805.
Nov 23 16:00:31.790 INFO Received unfit block header 128a80e3 at 805: already in store.
Nov 23 16:00:31.790 DEBG Processing header c82eec0a at 806.
Nov 23 16:00:31.791 INFO Received unfit block header c82eec0a at 806: already in store.
Nov 23 16:00:31.791 DEBG Processing header 32fc4a97 at 807.
Nov 23 16:00:31.791 DEBG Validating block with cuckoo size 16
Nov 23 16:00:31.792 DEBG Processing header 8adda078 at 808.
Nov 23 16:00:31.792 DEBG Validating block with cuckoo size 16
Nov 23 16:00:31.794 DEBG Processing header 04c2592d at 809.

Syncing will stop at block 806, and won't continue until restarting, which indicates there's some count or something that's not being kept up to date and is only re-init upon restart. This is consistent with widespread reports of having to continually stop and re-start the server to sync.

Indeed 806 is the last block we processed, and no further blocks will be requested until restart:

Nov 23 15:59:57.595 TRCE Hashing with additional data
Nov 23 15:59:57.597 DEBG Block at 806 with hash c82eec0a is valid, going to save and append.
Nov 23 15:59:57.598 INFO Updated head to c82eec0a at 806.
Nov 23 15:59:57.598 DEBG Committing sumtree extension.
Nov 23 15:59:57.602 DEBG Sumtree extension done.
Nov 23 15:59:57.602 DEBG adapter: notifying syncer: received block c82eec0a
Nov 23 15:59:57.603 DEBG Received block ffc152d6 at 334 from network, going to process.

@yeastplume
Copy link
Member Author

So in the code now, first question: why can we not just return the last block we've validated as the locator? On the other peer side, the locator just reconciles to a block we have in common:

  !·!·let heights = vec![tip.height];

  !·!·debug!(LOGGER, "Sync: locator heights: {:?}", heights);

We probably need to send a few to ensure we're finding a common block if there's a fork... Actually.. that may be the issue.. we're building that locator list based on the last block header height we've received rather than actual validated height.

@yeastplume
Copy link
Member Author

And indeed, spitting out that tip height:

Nov 23 16:24:59.286 DEBG tip height: 524

When only up to 54 has been validated. Surely we should be using 54 as our input to create the locator array?

@yeastplume
Copy link
Member Author

yeastplume commented Nov 23, 2017

My evolving understanding of how this is supposed to work probably needs correction, so I'll wait for comment before digging much further.

@yeastplume
Copy link
Member Author

... other way around. The height is being pulled from the header chain to build the locator array, but the locator ids themselves are being pulled from the full chain... not looking at code now, but 99% this is the winner

@yeastplume
Copy link
Member Author

Think we have this now from yesterday's dicussions

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant