lightning daemon stuck while paying an invoice.

[nachikettapas]

Steps to reproduce:
The setup consists of 12 nodes with bitcoin daemon running on single node while others connect to the this hub node (regtest network).

1. transfer 0.05 to all nodes lightning account.
2. open a channel from l2 to l1 and wait till it is public (funding 1000000) (l1 <- l2)
3. open a channel between l3 to l12 to l2 and wait till it is public (funding 1000000) (l2 <- l3 ... l2 <- l12)
4. generate invoice in l1 and is paid by l3. While paying the invoice, the payment gets stuck and fails.
5. After restarting the daemon, the payment goes successfully.

crash report

+824.880552995 lightningdUNUSUAL: Unable to estimate CONSERVATIVE/2 fee
+824.894203240 lightningdUNUSUAL: Unable to estimate ECONOMICAL/4 fee
+824.915556332 lightningdUNUSUAL: Unable to estimate ECONOMICAL/100 fee
+854.943194969 lightningdUNUSUAL: Unable to estimate CONSERVATIVE/2 fee
+854.954662768 lightningdUNUSUAL: Unable to estimate ECONOMICAL/4 fee
+854.966559409 lightningdUNUSUAL: Unable to estimate ECONOMICAL/100 fee
+907.286763972 lightningdUNUSUAL: Unable to estimate CONSERVATIVE/2 fee
+907.295797325 lightningdUNUSUAL: Unable to estimate ECONOMICAL/4 fee
+907.304022512 lightningdUNUSUAL: Unable to estimate ECONOMICAL/100 fee
+937.332353095 lightningdUNUSUAL: Unable to estimate CONSERVATIVE/2 fee
+937.339799522 lightningdUNUSUAL: Unable to estimate ECONOMICAL/4 fee
+937.350702806 lightningdUNUSUAL: Unable to estimate ECONOMICAL/100 fee
+978.688369386 lightningdUNUSUAL: Unable to estimate CONSERVATIVE/2 fee
+978.713864246 lightningdUNUSUAL: Unable to estimate ECONOMICAL/4 fee
+978.728731140 lightningdUNUSUAL: Unable to estimate ECONOMICAL/100 fee
+1008.743180649 lightningdUNUSUAL: Unable to estimate CONSERVATIVE/2 fee
+1008.751921200 lightningdUNUSUAL: Unable to estimate ECONOMICAL/4 fee
+1008.770015176 lightningdUNUSUAL: Unable to estimate ECONOMICAL/100 fee
+1037.679229683 lightningdBROKEN: FATAL SIGNAL 11 (version v0.8.0-222-g86c28b2)
+1037.679253883 lightningdBROKEN: backtrace: common/daemon.c:44 (send_backtrace) 0x43251a
+1037.679260044 lightningdBROKEN: backtrace: common/daemon.c:52 (crashdump) 0x432560
+1037.679265166 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7f93fa8c94af
+1037.679273167 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7f93fa8e2cc0
+1037.679278188 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7f93fa9ac9b4
+1037.679283606 lightningdBROKEN: backtrace: /usr/include/x86_64-linux-gnu/bits/stdio2.h:210 (vasprintf) 0x4160b0
+1037.679287586 lightningdBROKEN: backtrace: lightningd/log.c:393 (logv) 0x4160b0
+1037.679292875 lightningdBROKEN: backtrace: lightningd/log.c:457 (log_) 0x415fc2
+1037.679298117 lightningdBROKEN: backtrace: lightningd/jsonrpc.c:149 (destroy_jcon) 0x411d97
+1037.679304487 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:235 (notify) 0x473415
+1037.679309524 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:397 (del_tree) 0x4734b2
+1037.679313938 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:407 (del_tree) 0x4734e9
+1037.679319177 lightningdBROKEN: backtrace: ccan/ccan/tal/tal.c:481 (tal_free) 0x4739eb
+1037.679323830 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:450 (io_close) 0x469b07
+1037.679327663 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:401 (do_plan) 0x469b84
+1037.679335416 lightningdBROKEN: backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x469bce
+1037.679339849 lightningdBROKEN: backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x46b369
+1037.679344123 lightningdBROKEN: backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x411442
+1037.679348752 lightningdBROKEN: backtrace: lightningd/lightningd.c:928 (main) 0x414a5a
+1037.679353029 lightningdBROKEN: backtrace: (null):0 ((null)) 0x7f93fa8b482f
+1037.679356952 lightningdBROKEN: backtrace: (null):0 ((null)) 0x404088
+1037.679360296 lightningdBROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff

getinfo output

{
   "id": "0308f659229f3eb57545e70b5cfbb5a23cb943f5ef3348a63283f76713cc096228",
   "alias": "HOPPINGPENGUIN",
   "color": "0308f6",
   "num_peers": 1,
   "num_pending_channels": 0,
   "num_active_channels": 1,
   "num_inactive_channels": 0,
   "address": [],
   "binding": [
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "v0.8.0-222-g86c28b2",
   "blockheight": 659,
   "network": "regtest",
   "msatoshi_fees_collected": 0,
   "fees_collected_msat": "0msat",
   "lightning-dir": "/home/ubuntu/.lightning/regtest"
}

[ZmnSCPxj]

Can you elaborate on what you mean by "gets stuck"? pay does not return for a long time? What does paystatus on the invoice say while pay has not returned?

[nachikettapas]

Yes. the pay does not return for a long time. If I try to run paystatus, I get connection refused meaning the daemon has failed already.

Also, I am trying the setup on lxd containers for a test case, if it helps.

[rustyrussell]

So, l3 crashes? Interesting...

I suspect the pay plugin has actually crashed here (which is why your pay command doesn't terminate): is there anything coming out stderr?

When you abort the pay command, it then trips over this print statement:

		log_debug(jcon->log, "Abandoning command %s", c->json_cmd->name);

Since c->json_cmd has been freed as part of plugin destruction.

[rustyrussell]

Actually, I couldn't reproduce it on plugin crash. I did, however, reproduce it on plugin stop. Did you reload or unload the pay plugin? Either way, I'll fix the bug...