Handle JSONRPC disconnections gracefully about electrs

[greenaddress]

more instances

2018-07-16T00:52:28.407+00:00 - ERROR - server failed: Error: RPC failed: []                                                                                                                                       
Caused by: request failed: {"result":null,"error":{"code":-5,"message":"Transaction not in mempool"},"id":null}                                                                                                    
stack backtrace:                                                                                                                                                                                                   
   0:     0x55f75180ddac - backtrace::backtrace::trace::h44f27ad6608f02da                                                                                                                                          
   1:     0x55f75180d402 - backtrace::capture::Backtrace::new_unresolved::hb555da2dec445946                                                                                                                        
   2:     0x55f75180ccd7 - error_chain::backtrace::imp::InternalBacktrace::new::hc1c04021afee31b3                                                                                                                  
   3:     0x55f75180d044 - <error_chain::State as core::default::Default>::default::he24c386d1d298d64                                                                                                              
   4:     0x55f751748cf8 - electrs::daemon::Daemon::call_jsonrpc::h5148baa35ebacdad                                                                                                                                
   5:     0x55f75174978a - electrs::daemon::Daemon::requests::h9854bd24136c8b73                                                                                                                                    
   6:     0x55f75174beed - electrs::daemon::Daemon::gettransactions::h93b25cda33204a41                                                                                                                             
   7:     0x55f75178ace0 - electrs::mempool::Tracker::update::h9fe07ffc4b13e9f1                                                                                                                                    
   8:     0x55f75176802b - electrs::query::Query::update_mempool::h5a3567190cf4c2bb                                                                                                                                
   9:     0x55f751739df6 - electrs::main::h5294e30fc465d8cf                                                                                                                                                        
  10:     0x55f751738782 - std::rt::lang_start::{{closure}}::hc74e7e3dcbd83f22                                                                                                                                     
  11:     0x55f751bea4b2 - std::rt::lang_start_internal::{{closure}}::h72602870b4a34363                                                                                                                            
                        at libstd/rt.rs:59                                                                                                                                                                         
                         - std::panicking::try::do_call::hc2917ab2c572e22d                                                                                                                                         
                        at libstd/panicking.rs:310                                                                                                                                                                 
  12:     0x55f751c08469 - __rust_maybe_catch_panic                                                                                                                                                                
                        at libpanic_unwind/lib.rs:105                                                                                                                                                              
  13:     0x55f751bf19a5 - std::panicking::try::h3777f1f99a655493                                                                                                                                                  
                        at libstd/panicking.rs:289                                                                                                                                                                 
                         - std::panic::catch_unwind::hab6d1467193fc938                                                                                                                                             
                        at libstd/panic.rs:374                                                                                                                                                                     
                         - std::rt::lang_start_internal::h106bcdfb2e3beaf8                                                                                                                                         
                        at libstd/rt.rs:58                                                                                                                                                                         
  14:     0x55f75173a553 - main                                                                                                                                                                                    
  15:     0x7fb5c9cbd2b0 - __libc_start_main                                                                                                                                                                       
  16:     0x55f751732619 - _start                                                                                                                                                                                  
  17:                0x0 - <unknown>  

[greenaddress]

I think electrs maybe should fail with a user error message at start if it can't connect to the RPC and issue a call (i.e. getblockcount or similar). Once it is past that, maybe it should reconnect automatically with logs about it, possibly using some exponential retry capped at say 10 minutes and starting at 1 second or something like that.

[romanz]

Great suggestion, please feel free to open a PR 👍

[greenaddress]

More information based on some initial investigation:

it looks like the cookie changes at each restart, so rpc connection should re-read the cookie ideally.

[romanz]

@greenaddress May I help with this issue?

[greenaddress]

@romanz sorry I was away for a while and have a backlog of things. I still want to contribute but I'm not very seasoned with Rust (yet!) so I'm also slow. I don't have any commit yet for this issue so if you want to take over I'll be happy to help review or test.

[romanz]

No problem :)
I'll push some refactoring work to the disconnect branch - it should help us to handle disconnections.

[greenaddress]

@romanz I briefly tested 6efab9c

My immediate test was trying to restart bitcoin core and that made it crash. I didn't try some disconnect (but i think i could simulate with a tunnel/port forwarding)

[romanz]

Thanks for testing!
Could you please attach the panic message/backtrace?

[romanz]

@greenaddress Please try 9ee92c8 - AFAIK it should handle bitcoind restarts:

$ GPG SSH cargo run --release -- -vvvv --timestamp --network=testnet --db-dir ./test-db/
    Finished release [optimized] target(s) in 0.09s
     Running `target/release/electrs -vvvv --timestamp --network=testnet --db-dir ./test-db/`
Config { log: StdErrLog { verbosity: Trace, quiet: false, timestamp: Millisecond, modules: [], writer: "stderr", color_choice: Auto }, network_type: Testnet, db_path: "./test-db/testnet", daemon_dir: "/home/roman/.bitcoin/testnet3", daemon_rpc_addr: V4(127.0.0.1:18332), cookie: None, electrum_rpc_addr: V4(127.0.0.1:60001), monitoring_addr: V4(127.0.0.1:42024), skip_bulk_import: false }
2018-07-28T18:19:17.973+03:00 - DEBUG - Server listening on 127.0.0.1:42024
2018-07-28T18:19:17.973+03:00 - DEBUG - Running accept thread
2018-07-28T18:19:17.975+03:00 - DEBUG - BlockchainInfo { chain: "test", blocks: 1355891, headers: 1355891, bestblockhash: "000000000000375e2c3b170f57a6e1d988891c77e2f33531c3e02fc3f6d77fdd", size_on_disk: 14498976210, pruned: false }
2018-07-28T18:19:17.975+03:00 - DEBUG - NetworkInfo { version: 169900, subversion: "/Satoshi:0.16.99/" }
2018-07-28T18:19:17.975+03:00 - DEBUG - opening DB at "./test-db/testnet"
2018-07-28T18:19:18.263+03:00 - TRACE - closing DB at "./test-db/testnet"
2018-07-28T18:19:18.263+03:00 - DEBUG - opening DB at "./test-db/testnet"
2018-07-28T18:19:26.344+03:00 - DEBUG - applying 1355891 new headers from height 0
2018-07-28T18:19:26.924+03:00 - DEBUG - downloading new block headers (1355891 already indexed) from 000000000000375e2c3b170f57a6e1d988891c77e2f33531c3e02fc3f6d77fdd
2018-07-28T18:19:26.924+03:00 - TRACE - downloaded 1 block headers
2018-07-28T18:19:26.924+03:00 - INFO - best=000000000000375e2c3b170f57a6e1d988891c77e2f33531c3e02fc3f6d77fdd height=1355891 @ 2018-07-28T15:17:30Z (1 left to index)
2018-07-28T18:19:27.129+03:00 - DEBUG - applying 1 new headers from height 1355891
2018-07-28T18:19:27.130+03:00 - TRACE - 279 transactions in mempool (+279)
2018-07-28T18:19:27.179+03:00 - INFO - RPC server running on 127.0.0.1:60001
2018-07-28T18:19:32.224+03:00 - TRACE - 280 transactions in mempool (+1)
2018-07-28T18:19:37.225+03:00 - WARN - connection failed: failed to read cookie from "/home/roman/.bitcoin/testnet3/.cookie"
2018-07-28T18:19:40.226+03:00 - WARN - failed to connect daemon at 127.0.0.1:18332: Connection refused (os error 111)
2018-07-28T18:19:43.226+03:00 - WARN - failed to connect daemon at 127.0.0.1:18332: Connection refused (os error 111)
2018-07-28T18:19:46.226+03:00 - WARN - failed to connect daemon at 127.0.0.1:18332: Connection refused (os error 111)
2018-07-28T18:19:49.227+03:00 - WARN - connection failed: request failed "HTTP/1.1 500 Internal Server Error"
2018-07-28T18:19:52.227+03:00 - WARN - connection failed: request failed "HTTP/1.1 500 Internal Server Error"
2018-07-28T18:19:55.228+03:00 - WARN - connection failed: request failed "HTTP/1.1 500 Internal Server Error"
2018-07-28T18:19:58.228+03:00 - WARN - connection failed: request failed "HTTP/1.1 500 Internal Server Error"
2018-07-28T18:20:01.232+03:00 - TRACE - 280 transactions in mempool (+0)
2018-07-28T18:20:06.276+03:00 - TRACE - 280 transactions in mempool (+0)
2018-07-28T18:20:11.324+03:00 - TRACE - 332 transactions in mempool (+52)

[greenaddress]

@romanz yep fixed now in 91e4dd8

[romanz]

Cool, thanks for testing!