search

mimblewimble / grin

Minimal implementation of the Mimblewimble protocol.
https://grin.mw/
Apache License 2.0
5.04k stars 992 forks source link

"grin server run" crashes with "Failed to download required block" #344

Closed bit closed 6 years ago

bit commented 6 years ago

stuck on an orphaned chain, server started to crash with the following error:

thread 'syncer' panicked at 'Failed to download required block d5bf8573', grin/src/sync.rs:192:4                    
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.                             
stack backtrace:                                                                                                    
   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:381                                                               
   3: std::panicking::default_hook                                                                                  
             at /checkout/src/libstd/panicking.rs:397                                                               
   4: std::panicking::rust_panic_with_hook                                                                          
             at /checkout/src/libstd/panicking.rs:611                                                               
   5: std::panicking::begin_panic                                                                                   
             at /checkout/src/libstd/panicking.rs:572                                                               
   6: std::panicking::begin_panic_fmt                                                                               
             at /checkout/src/libstd/panicking.rs:522                                                               
   7: grin_grin::sync::Syncer::request_bodies                                                                       
             at grin/src/sync.rs:192                                                                                
   8: grin_grin::sync::Syncer::run                                                                                  
             at grin/src/sync.rs:137                                                                                
   9: grin_grin::adapters::NetToChainAdapter::start_sync::{{closure}}                                               
             at grin/src/adapters.rs:274                                                                            
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "PoisonError { inner: .. }"', /checkout/src/
libcore/result.rs:906:4                                                                                             
stack backtrace:                                                                                                    
   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:381                                                               
   3: std::panicking::default_hook                                                                                  
             at /checkout/src/libstd/panicking.rs:397                                                               
   4: std::panicking::rust_panic_with_hook                                                                          
             at /checkout/src/libstd/panicking.rs:611                                                               
   5: std::panicking::begin_panic                                                                                   
             at /checkout/src/libstd/panicking.rs:572                                                               
   6: std::panicking::begin_panic_fmt                                                                               
             at /checkout/src/libstd/panicking.rs:522                                                               
   7: rust_begin_unwind                                                                                             
             at /checkout/src/libstd/panicking.rs:498                                                               
   8: core::panicking::panic_fmt                                                                                    
             at /checkout/src/libcore/panicking.rs:71                                                               
   9: core::result::unwrap_failed                                                                                   
             at /checkout/src/libcore/macros.rs:41                                                                  
  10: <core::result::Result<T, E>>::unwrap                                                                          
             at /checkout/src/libcore/result.rs:772                                                                 
  11: grin_grin::sync::Syncer::headers_received                                                                     
             at grin/src/sync.rs:263                                                                                
  12: <grin_grin::adapters::NetToChainAdapter as grin_p2p::types::NetAdapter>::headers_received                     
             at grin/src/adapters.rs:138                                                                            
  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:191
  15: <grin_p2p::protocol::ProtocolV1 as grin_p2p::types::Protocol>::handle::{{closure}}
             at p2p/src/protocol.rs:52
  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}}                                                
             at p2p/src/conn.rs:215                                                                                 
  20: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::{{closure}}::{{closure}}      
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/and_then.rs:34 
  21: <core::result::Result<T, E>>::map                                                                             
             at /checkout/src/libcore/result.rs:468                                                                 
  22: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::{{closure}}                   
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/and_then.rs:33 
  23: <futures::future::chain::Chain<A, B, C>>::poll                                                                
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/chain.rs:39    
  24: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll                                
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/and_then.rs:32 
  25: <futures::stream::fold::Fold<S, F, Fut, T> as futures::future::Future>::poll                                  
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/stream/fold.rs:70     
  26: <alloc::boxed::Box<F> as futures::future::Future>::poll                                                       
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/mod.rs:113     
  27: <futures::future::map::Map<A, F> as futures::future::Future>::poll                                            
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map.rs:30      
  28: <futures::future::select::Select<A, B> as futures::future::Future>::poll                                      
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/select.rs:48   
  29: <futures::future::map::Map<A, F> as futures::future::Future>::poll                                            
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map.rs:30      
  30: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll                                     
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map_err.rs:30  
  31: <futures::future::select::Select<A, B> as futures::future::Future>::poll                                      
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/select.rs:52   
  32: <futures::future::map::Map<A, F> as futures::future::Future>::poll                                            
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map.rs:30      
  33: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll                                     
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map_err.rs:30  
  34: <alloc::boxed::Box<F> as futures::future::Future>::poll                                                       
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/mod.rs:113     
  35: <futures::future::select::Select<A, B> as futures::future::Future>::poll                                      
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/select.rs:48   
  36: <futures::future::map::Map<A, F> as futures::future::Future>::poll                                            
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map.rs:30      
  37: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll                                     
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map_err.rs:30  
  38: <alloc::boxed::Box<F> as futures::future::Future>::poll                                                       
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/mod.rs:113     
  39: <futures::future::chain::Chain<A, B, C>>::poll                                                                
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/chain.rs:26    
  40: <futures::future::then::Then<A, B, F> as futures::future::Future>::poll                                                    at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/then.rs:32
  41: <alloc::boxed::Box<F> as futures::future::Future>::poll                                                                    at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/mod.rs:113
  42: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll                                    
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/map_err.rs:30    43: <alloc::boxed::Box<F> as futures::future::Future>::poll                                               
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/future/mod.rs:113
  44: <futures::task_impl::Spawn<T>>::poll_future_notify::{{closure}}                                                            at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/task_impl/mod.rs:288
  45: <futures::task_impl::Spawn<T>>::enter::{{closure}}                                                                         at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/task_impl/mod.rs:362
  46: futures::task_impl::std::set                                                                              
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/task_impl/std/mod.rs:78                                                                                                                     47: <futures::task_impl::Spawn<T>>::enter                                                                 
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/task_impl/mod.rs:362    48: <futures::task_impl::Spawn<T>>::poll_future_notify
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.17/src/task_impl/mod.rs:288    49: tokio_core::reactor::Core::dispatch_task::{{closure}}
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:356
  50: <scoped_tls::ScopedKey<T>>::set                                                                                            at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/scoped-tls-0.1.0/src/lib.rs:135
  51: tokio_core::reactor::Core::dispatch_task                                                                  
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:355   52: tokio_core::reactor::Core::dispatch
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:316
  53: tokio_core::reactor::Core::poll                                         
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:304   54: tokio_core::reactor::Core::run                                                                        
             at /home/grin/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:241
  55: grin_grin::server::Server::start                                                                        
             at grin/src/server.rs:76                                          
  56: grin::server_command                                                                                                       at src/bin/grin.rs:341
  57: grin::main                                                              
             at src/bin/grin.rs:270                                                                                   58: __rust_maybe_catch_panic
             at /checkout/src/libpanic_unwind/lib.rs:99                 
  59: std::rt::lang_start                                                                                     
             at /checkout/src/libstd/panicking.rs:459                          
             at /checkout/src/libstd/panic.rs:361                                                                                at /checkout/src/libstd/rt.rs:61
  60: main                                                   
  61: __libc_start_main                                                                                        
  62: _start
ignopeverell commented 6 years ago

You should see a line like this in your logs:

DEBG monitoring peers(21)

Can you tell me what that number is for you?

bit commented 6 years ago

between 

DEBG monitoring peers (8)

and 

DEBG monitoring peers (14)

not quite sure what it was at the time of the error, can try to run with the failing chain again to trigger it again.

andybellenie commented 6 years ago

I'm seeing the same error, here's a log extract before it happened

Nov 21 17:45:22.482 DEBG Received block 274848f8 at 7171 from network, going to process.
Nov 21 17:45:22.482 DEBG Processing block 274848f8 at 7171 with 0 inputs and 1 outputs.
Nov 21 17:45:22.482 DEBG Block 274848f8 refused by chain: Orphan
Nov 21 17:45:23.059 TRCE Too long: Block Some(274848f8)
Nov 21 17:45:23.059 INFO Client 35.196.208.76:13414 connection lost: Timeout
Nov 21 17:45:24.388 DEBG Sync: peer 28786039 vs us 28786039
Nov 21 17:45:24.388 DEBG Sync: blocks to download 134, block downloading 8
Nov 21 17:45:24.388 DEBG Retry 9 on block e4bb814a
Nov 21 17:45:24.389 DEBG Requesting block e4bb814a from peer 185.8.164.22:13414.
Nov 21 17:45:24.389 DEBG Retry 3 on block 027c89a0
Nov 21 17:45:24.389 DEBG Requesting block 027c89a0 from peer 174.138.116.153:13414.
Nov 21 17:45:24.389 DEBG Retry 3 on block 3a239caa
Nov 21 17:45:24.389 DEBG Requesting block 3a239caa from peer 185.8.164.22:13414.
Nov 21 17:45:24.389 DEBG Requested 0 full blocks to download, total left: 134. Current list: [BlockDownload { hash: 1bc95908, start_time: Instant { t: 1142501847396130 }, retries: 11 }, BlockDownload { hash: 3864054c, start_time: Instant { t: 1142501847450874 }, retries: 11 }, BlockDownload { hash: c29227aa, start_time: Instant { t: 1142501847531763 }, retries: 11 }, BlockDownload { hash: fdf6b667, start_time: Instant { t: 1142501847588665 }, retries: 11 }, BlockDownload { hash: 274848f8, start_time: Instant { t: 1142501847645657 }, retries: 11 }, BlockDownload { hash: e4bb814a, start_time: Instant { t: 1142509855959140 }, retries: 10 }, BlockDownload { hash: 027c89a0, start_time: Instant { t: 1142540562965612 }, retries: 4 }, BlockDownload { hash: 3a239caa, start_time: Instant { t: 1142540563070359 }, retries: 4 }].
Nov 21 17:45:24.486 DEBG Received block 027c89a0 at 7173 from network, going to process.
Nov 21 17:45:24.486 DEBG Processing block 027c89a0 at 7173 with 0 inputs and 1 outputs.
Nov 21 17:45:24.486 DEBG Block 027c89a0 refused by chain: Orphan
Nov 21 17:45:24.665 DEBG monitoring peers (8)
Nov 21 17:45:24.665 DEBG cleaning V4(35.196.208.76:13414), not connected
Nov 21 17:45:24.665 DEBG cleaning V4(138.68.30.5:13414), not connected
Nov 21 17:45:24.665 DEBG cleaning V4(147.75.66.147:13414), not connected
Nov 21 17:45:24.667 DEBG Got 8 peers from db, trying to connect.
Nov 21 17:45:24.667 DEBG New peer address to connect to: 147.75.66.147:13414.
Nov 21 17:45:24.668 DEBG 0.0.0.0:13414 connecting to 147.75.66.147:13414
Nov 21 17:45:24.669 DEBG New peer address to connect to: 192.241.168.77:13414.
Nov 21 17:45:24.669 DEBG 0.0.0.0:13414 connecting to 192.241.168.77:13414
Nov 21 17:45:24.669 DEBG New peer address to connect to: 104.131.80.108:13414.
Nov 21 17:45:24.670 DEBG 0.0.0.0:13414 connecting to 104.131.80.108:13414
Nov 21 17:45:24.670 DEBG New peer address to connect to: 138.68.30.5:13414.
Nov 21 17:45:24.670 DEBG 0.0.0.0:13414 connecting to 138.68.30.5:13414
Nov 21 17:45:24.671 DEBG New peer address to connect to: 88.99.251.87:13414.
Nov 21 17:45:24.671 DEBG 0.0.0.0:13414 connecting to 88.99.251.87:13414
Nov 21 17:45:24.672 DEBG New peer address to connect to: 94.130.66.48:13414.
Nov 21 17:45:24.672 DEBG 0.0.0.0:13414 connecting to 94.130.66.48:13414
Nov 21 17:45:24.673 DEBG New peer address to connect to: 107.184.47.93:13414.
Nov 21 17:45:24.673 DEBG 0.0.0.0:13414 connecting to 107.184.47.93:13414
Nov 21 17:45:24.673 DEBG New peer address to connect to: 35.196.208.76:13414.
Nov 21 17:45:24.674 DEBG 0.0.0.0:13414 connecting to 35.196.208.76:13414
Nov 21 17:45:24.675 DEBG event loop running
Nov 21 17:45:24.713 DEBG handshake connect with nonce - 5295519764074690727, sender - V4(0.0.0.0:13414), receiver - V4(94.130.66.48:13414)
Nov 21 17:45:24.714 DEBG handshake connect with nonce - 15957970559384594153, sender - V4(0.0.0.0:13414), receiver - V4(88.99.251.87:13414)
Nov 21 17:45:24.765 DEBG handshake connect with nonce - 9250590781963917827, sender - V4(0.0.0.0:13414), receiver - V4(147.75.66.147:13414)
Nov 21 17:45:24.769 DEBG handshake connect with nonce - 9578971067194630102, sender - V4(0.0.0.0:13414), receiver - V4(192.241.168.77:13414)
Nov 21 17:45:24.770 DEBG handshake connect with nonce - 9178087956916380448, sender - V4(0.0.0.0:13414), receiver - V4(104.131.80.108:13414)
Nov 21 17:45:24.820 DEBG handshake connect with nonce - 18003580162641636602, sender - V4(0.0.0.0:13414), receiver - V4(35.196.208.76:13414)
Nov 21 17:45:24.821 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(88.99.251.87:13414), total_difficulty: Difficulty { num: 26835022 } }
Nov 21 17:45:24.821 DEBG Saving newly connected peer 88.99.251.87:13414.
Nov 21 17:45:24.821 DEBG saving peer to store PeerData { addr: V4(88.99.251.87:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:24.822 DEBG Asking 88.99.251.87:13414 for more peers.
Nov 21 17:45:24.823 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(94.130.66.48:13414), total_difficulty: Difficulty { num: 20417457 } }
Nov 21 17:45:24.823 DEBG Saving newly connected peer 94.130.66.48:13414.
Nov 21 17:45:24.823 DEBG saving peer to store PeerData { addr: V4(94.130.66.48:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:24.826 DEBG Asking 94.130.66.48:13414 for more peers.
Nov 21 17:45:24.871 DEBG handshake connect with nonce - 12845513341387070533, sender - V4(0.0.0.0:13414), receiver - V4(107.184.47.93:13414)
Nov 21 17:45:24.871 DEBG handshake connect with nonce - 17940639537637319856, sender - V4(0.0.0.0:13414), receiver - V4(138.68.30.5:13414)
Nov 21 17:45:24.896 DEBG Received 170 peer addrs, saving.
Nov 21 17:45:24.902 DEBG Received 189 peer addrs, saving.
Nov 21 17:45:24.989 INFO Client 174.138.116.153:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 21 17:45:25.075 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(147.75.66.147:13414), total_difficulty: Difficulty { num: 27399553 } }
Nov 21 17:45:25.076 DEBG Saving newly connected peer 147.75.66.147:13414.
Nov 21 17:45:25.076 DEBG saving peer to store PeerData { addr: V4(147.75.66.147:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:25.077 DEBG Asking 147.75.66.147:13414 for more peers.
Nov 21 17:45:25.078 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(192.241.168.77:13414), total_difficulty: Difficulty { num: 28045837 } }
Nov 21 17:45:25.078 DEBG Saving newly connected peer 192.241.168.77:13414.
Nov 21 17:45:25.078 DEBG saving peer to store PeerData { addr: V4(192.241.168.77:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:25.079 DEBG Asking 192.241.168.77:13414 for more peers.
Nov 21 17:45:25.080 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(104.131.80.108:13414), total_difficulty: Difficulty { num: 28786039 } }
Nov 21 17:45:25.080 DEBG Saving newly connected peer 104.131.80.108:13414.
Nov 21 17:45:25.080 DEBG saving peer to store PeerData { addr: V4(104.131.80.108:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:25.082 DEBG Asking 104.131.80.108:13414 for more peers.
Nov 21 17:45:25.161 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(35.196.208.76:13414), total_difficulty: Difficulty { num: 27700011 } }
Nov 21 17:45:25.161 DEBG Saving newly connected peer 35.196.208.76:13414.
Nov 21 17:45:25.161 DEBG saving peer to store PeerData { addr: V4(35.196.208.76:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:25.163 DEBG Asking 35.196.208.76:13414 for more peers.
Nov 21 17:45:25.166 DEBG Received 119 peer addrs, saving.
Nov 21 17:45:25.183 DEBG Received 160 peer addrs, saving.
Nov 21 17:45:25.202 DEBG Received 122 peer addrs, saving.
Nov 21 17:45:25.264 DEBG Received 52 peer addrs, saving.
Nov 21 17:45:25.375 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(107.184.47.93:13414), total_difficulty: Difficulty { num: 20417457 } }
Nov 21 17:45:25.375 DEBG Saving newly connected peer 107.184.47.93:13414.
Nov 21 17:45:25.375 DEBG saving peer to store PeerData { addr: V4(107.184.47.93:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:25.376 DEBG Asking 107.184.47.93:13414 for more peers.
Nov 21 17:45:25.394 INFO Connected to peer PeerInfo { capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", version: 1, addr: V4(138.68.30.5:13414), total_difficulty: Difficulty { num: 27708665 } }
Nov 21 17:45:25.394 DEBG Saving newly connected peer 138.68.30.5:13414.
Nov 21 17:45:25.395 DEBG saving peer to store PeerData { addr: V4(138.68.30.5:13414), capabilities: FULL_HIST | UTXO_HIST | PEER_LIST | FULL_NODE, user_agent: "MW/Grin 0.1", flags: Healthy }
Nov 21 17:45:25.396 DEBG Asking 138.68.30.5:13414 for more peers.
Nov 21 17:45:25.540 DEBG Received 49 peer addrs, saving.
Nov 21 17:45:25.613 DEBG Received 69 peer addrs, saving.
Nov 21 17:45:26.391 DEBG Sync: peer 28786039 vs us 28786039
Nov 21 17:45:26.391 DEBG Sync: blocks to download 134, block downloading 8
Nov 21 17:45:26.391 DEBG Loc heights: [7308, 7306, 7304, 7300, 7292, 7276, 7244, 7180, 7052, 6796, 0]
Nov 21 17:45:26.716 TRCE Too long: Block Some(027c89a0)
Nov 21 17:45:26.716 INFO Client 185.8.164.22:13414 connection lost: Timeout
Nov 21 17:45:26.961 DEBG Asking peer 104.131.80.108:13414 for more block headers, locator: [45ca96e5, 8ad50c35, 1225b1e5, fd957e9a, b7a3e683, 1af2f299, 2a584c9d, 946bcc16, 336b8f98, d66d7082, e17ea64f]
Nov 21 17:45:26.961 DEBG Retry 11 on block 1bc95908
Nov 21 17:45:26.961 DEBG Requesting block 1bc95908 from peer 185.8.164.22:13414.
Nov 21 17:45:26.961 DEBG Error requesting block: ConnectionClose
Nov 21 17:45:26.961 DEBG Retry 11 on block 3864054c
Nov 21 17:45:26.961 DEBG Requesting block 3864054c from peer 51.255.202.83:13414.
Nov 21 17:45:26.961 DEBG Retry 11 on block c29227aa
Nov 21 17:45:26.961 DEBG Requesting block c29227aa from peer 51.255.202.83:13414.
Nov 21 17:45:26.961 DEBG Retry 11 on block fdf6b667
Nov 21 17:45:26.962 DEBG Requesting block fdf6b667 from peer 165.227.63.166:13414.
Nov 21 17:45:26.962 DEBG Retry 11 on block 274848f8
Nov 21 17:45:26.962 DEBG Requesting block 274848f8 from peer 192.241.168.77:13414.
Nov 21 17:45:26.962 DEBG Requested 0 full blocks to download, total left: 134. Current list: [BlockDownload { hash: 1bc95908, start_time: Instant { t: 1142501847396130 }, retries: 12 }, BlockDownload { hash: 3864054c, start_time: Instant { t: 1142501847450874 }, retries: 12 }, BlockDownload { hash: c29227aa, start_time: Instant { t: 1142501847531763 }, retries: 12 }, BlockDownload { hash: fdf6b667, start_time: Instant { t: 1142501847588665 }, retries: 12 }, BlockDownload { hash: 274848f8, start_time: Instant { t: 1142501847645657 }, retries: 12 }, BlockDownload { hash: e4bb814a, start_time: Instant { t: 1142509855959140 }, retries: 10 }, BlockDownload { hash: 027c89a0, start_time: Instant { t: 1142540562965612 }, retries: 4 }, BlockDownload { hash: 3a239caa, start_time: Instant { t: 1142540563070359 }, retries: 4 }].
Nov 21 17:45:26.984 DEBG Received block 3864054c at 7168 from network, going to process.
Nov 21 17:45:26.984 DEBG Processing block 3864054c at 7168 with 0 inputs and 1 outputs.
Nov 21 17:45:26.985 DEBG Block 3864054c refused by chain: Orphan
Nov 21 17:45:27.002 DEBG Received block c29227aa at 7169 from network, going to process.
Nov 21 17:45:27.002 DEBG Processing block c29227aa at 7169 with 0 inputs and 1 outputs.
Nov 21 17:45:27.002 DEBG Block c29227aa refused by chain: Orphan
Nov 21 17:45:27.047 INFO Received 0 block headers
Nov 21 17:45:27.047 INFO Added 0 headers to the header chain.
Nov 21 17:45:27.144 DEBG Received block fdf6b667 at 7170 from network, going to process.
Nov 21 17:45:27.144 DEBG Processing block fdf6b667 at 7170 with 0 inputs and 1 outputs.
Nov 21 17:45:27.144 DEBG Block fdf6b667 refused by chain: Orphan
Nov 21 17:45:28.965 DEBG Sync: peer 28786039 vs us 28786039
Nov 21 17:45:28.965 DEBG Sync: blocks to download 134, block downloading 8
andybellenie commented 6 years ago

Exact message: thread 'syncer' panicked at 'Failed to download required block 1bc95908', grin/src/sync.rs:192:4

AsrielBelacqua commented 6 years ago

I just hit this, too, leaving me on an orphaned chain also. Full debug log: grin-failed-download.log.gz

Just before the panic, I saw:

Nov 22 22:23:54.180 DEBG monitoring peers (9)
AsrielBelacqua commented 6 years ago

And another one: grin-failed-download2.log.gz

This time, there are a number of obvious retries:

Nov 22 22:53:15.033 DEBG Sync: Retry 11 on block b585b73f
Nov 22 22:53:15.033 DEBG Requesting block b585b73f from peer 104.131.80.108:13414.
Nov 22 22:53:15.033 DEBG Sync: Retry 10 on block 7e010923
Nov 22 22:53:15.033 DEBG Requesting block 7e010923 from peer 35.196.208.76:13414.
Nov 22 22:53:15.034 DEBG Sync: Retry 2 on block 8817cf75
Nov 22 22:53:15.034 DEBG Requesting block 8817cf75 from peer 185.8.164.22:13414.
Nov 22 22:53:15.034 DEBG Sync: Retry 2 on block 696ddb4a
Nov 22 22:53:15.034 DEBG Requesting block 696ddb4a from peer 35.196.208.76:13414.
Nov 22 22:53:15.034 DEBG Sync: Retry 2 on block f02e2220
Nov 22 22:53:15.034 DEBG Requesting block f02e2220 from peer 91.134.132.74:13414.
Nov 22 22:53:15.034 DEBG Sync: Retry 2 on block 9313c833
Nov 22 22:53:15.034 DEBG Requesting block 9313c833 from peer 109.74.202.16:13414.

and then disconnects (after the panic):

Nov 22 22:53:17.972 INFO Client 37.59.48.28:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 22 22:53:17.975 INFO Client 91.134.132.74:13414 connection lost: Timeout
Nov 22 22:53:17.975 INFO Client 88.99.251.87:13414 connection lost: Timeout
Nov 22 22:53:17.976 INFO Client 185.8.164.22:13414 connection lost: Timeout
Nov 22 22:53:17.976 DEBG peer total_diff (ping/pong): 109.74.202.16:13414, 28801427 vs us 27480645
Nov 22 22:53:17.976 INFO Client 109.74.202.16:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 22 22:53:17.976 DEBG peer total_diff (ping/pong): 34.225.3.108:13414, 28873185 vs us 27480645
Nov 22 22:53:17.978 INFO Client 34.225.3.108:13414 connection lost: Timeout
Nov 22 22:53:17.978 INFO Client 147.75.66.147:13414 connection lost: Timeout
Nov 22 22:53:17.978 DEBG peer total_diff (ping/pong): 104.131.80.108:13414, 26895661 vs us 27480645
Nov 22 22:53:17.980 DEBG peer total_diff (ping/pong): 51.15.219.12:13414, 9444927 vs us 27480645
Nov 22 22:53:17.991 INFO Client 51.15.219.12:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 22 22:53:17.992 INFO Client 108.253.243.102:13414 connection lost: Timeout
Nov 22 22:53:17.992 DEBG peer total_diff (ping/pong): 165.227.63.166:13414, 29514081 vs us 27480645
Nov 22 22:53:17.993 INFO Client 165.227.63.166:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 22 22:53:17.994 DEBG peer total_diff (ping/pong): 192.241.168.77:13414, 29295183 vs us 27480645
Nov 22 22:53:17.995 INFO Client 192.241.168.77:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 22 22:53:17.995 DEBG peer total_diff (ping/pong): 35.196.208.76:13414, 0 vs us 27480645
Nov 22 22:53:17.996 INFO Client 35.196.208.76:13414 connection lost: Connection(Error { repr: Custom(Custom { kind: UnexpectedEof, error: StringError("early eof") }) })
Nov 22 22:53:17.998 DEBG monitoring peers (15)
Nov 22 22:53:17.998 DEBG cleaning V4(91.134.132.74:13414), not connected
Nov 22 22:53:17.999 DEBG cleaning V4(37.59.48.28:13414), not connected
Nov 22 22:53:17.999 DEBG cleaning V4(185.8.164.22:13414), not connected
Nov 22 22:53:18.000 DEBG cleaning V4(94.130.66.48:13414), not connected
Nov 22 22:53:18.000 DEBG cleaning V4(108.253.243.102:13414), not connected
Nov 22 22:53:18.000 DEBG cleaning V4(88.99.251.87:13414), not connected
Nov 22 22:53:18.000 DEBG cleaning V4(34.225.3.108:13414), not connected
Nov 22 22:53:18.001 DEBG cleaning V4(109.74.202.16:13414), not connected
Nov 22 22:53:18.001 DEBG cleaning V4(174.138.116.153:13414), not connected
Nov 22 22:53:18.001 DEBG cleaning V4(192.241.168.77:13414), not connected
Nov 22 22:53:18.002 DEBG cleaning V4(165.227.63.166:13414), not connected
Nov 22 22:53:18.003 DEBG cleaning V4(51.15.219.12:13414), not connected
Nov 22 22:53:18.004 DEBG cleaning V4(35.196.208.76:13414), not connected
Nov 22 22:53:18.005 DEBG cleaning V4(147.75.66.147:13414), not connected
Nov 22 22:53:18.017 DEBG Got 14 peers from db, trying to connect.
Nov 22 22:53:18.019 DEBG checking the nonce - 13037667012191003389, RwLockReadGuard { lock: RwLock { data: [13734815633455481345, 13325952091174310921, 11091004595242970959, 17799760244487192389, 7649194345018259032, 8499049659895545550, 13131287644826261920, 8689517968596326917, 11851392860968653373, 13061495518362722332, 13316598398447439991, 11740891684982742077, 7071063339546696746, 15993458088577323719, 15462279776721111243, 5712333047746409678, 12737737619932569083, 2355340528747330990, 7181220363559087623, 16944650164497825276, 6037259315374053247, 2577101784468059578, 9367370745561070410, 6784605649432459937, 15139358158675457326, 5127559872747684538, 12858538101961879274, 1000715642615689556, 18269969920003193535, 11993409390697588197, 11272151152986371715, 13219917426668750191, 12053993013588095547, 8768170106903483938, 10986635076923340828, 10809800048014300758, 8876419155830100148, 4834340132671308759, 12117920573029612510, 12872126322794670262, 17288885989454510802, 5112374297440412880, 15993318917597480921, 17115443448777414859, 10234242211131390515, 8655481950857702173, 13632499688368443761, 17053314559514934283, 13118139629571882875, 17141949515070538740, 14380645450655827007, 10218096442097110049, 6668912817886784539, 9315512451437797292, 7053882340533447634, 17973753908690141103, 15141305418920244711, 15126816087329794827, 4149048955742363754, 17390451318422857737, 941398121273115668, 10689488104482354307, 15517901265057391907, 7847774722856450808, 6222225663849658932, 10665373567600709969, 881741377949239716, 1111958401049354058, 8061533745407185074, 501825927051848368, 4298471846585043350, 5733574552251533864, 1798192755310178426, 7351912150338942772, 14111445456907365196, 10615485165430649814, 10278594666339366461, 8224338387759830565, 4131023541029422511, 14223721118783469538, 12226194130406245751, 3303151492859031228, 3716162048768353337, 3110888622331799313, 5799065123629545613, 4918009912774138359, 13130162283175058548, 4439135164011109605, 17958531122865373477, 17819624528569745789, 15251353074855989377, 7275619330596500276, 9840122250513070311, 7804396242757851582, 11313255329978644276, 10238825711035775141, 2823116918878180065, 8440155270478925968, 6110158766453293323] } }
Nov 22 22:53:18.020 DEBG extract_ip - 0.0.0.0, Ok(V4(109.74.202.16:33434))
Nov 22 22:53:18.020 DEBG Success handshake with 109.74.202.16:13414.
yeastplume commented 6 years ago

I've seen this a couple of times on a node now doing a full sync, and it doesn't appear to be about dropping peers. Each time it was a stubborn block that was refused again and again for having something wrong with it, and instead of rewinding/finding another peer with a better chain. Restarting each time also got past the bad block.

I think what's outlined https://github.com/mimblewimble/grin/issues/369 will be at least a part fix for this.

AsrielBelacqua commented 6 years ago

Interesting, and yes I also noticed that restarting successfully gets past the bad block. It is also curious that this machine often hits #305 even though I am sure that there are no general connectivity problems on that node. But if as you say this isn't about dropping peers, then perhaps the two issues do indeed have distinct causes (in spite of the surprising coincidence).

ignopeverell commented 6 years ago

We're trying to track most sync issues under doc/usage.md. Thanks for the testing!