Wallet software dies after making a payment (whether successful or not), taking lightningd down with it

[NateNate60]

Steps to reproduce

• Pay a node that is a significant distance away (no direct channels). I tried Fixedfloat (failed to route) and u/lntipbot (there exists several possible routes from my node to theirs)
• Wait around 10 seconds

The following happens (from the FixedFloat test):

nate@nates-server:~$ spark-wallet --ln-path /home/nate/.lightning/bitcoin --port 9737 --host 0.0.0.0 --tls-name [                ] --no-rates
Connected to c-lightning v0.9.0-44-g01a82d3 with id [                                                                         ] on network bitcoin at /home/nate/.lightning/bitcoin/lightning-rpc
Loaded TLS certificate with fingerprint [                                                           ] from /home/nate/.spark-wallet/tls

HTTPS server running on https://0.0.0.0:9737
POST /rpc 200 277.076 ms - 652
POST /rpc 200 5.974 ms - -
POST /rpc 200 3.486 ms - 581
POST /rpc 200 3.590 ms - -
GET /stream?access-key=[                                                                        ] 200 7.786 ms - -
POST /rpc 200 11.961 ms - 581
POST /rpc 200 13.309 ms - -
POST /rpc 200 12.715 ms - -
POST /rpc 200 11.256 ms - -
POST /rpc 200 25.906 ms - -
POST /rpc 200 10.495 ms - -
POST /rpc 200 1.896 ms - -
POST /rpc 200 2.592 ms - 581
POST /rpc 200 2.446 ms - 566
POST /rpc 200 2.878 ms - -
LightningError: Ran out of routes to try after 187 attempts: see `paystatus`
    at createError (/usr/local/lib/node_modules/spark-wallet/node_modules/error/typed.js:40:22)
    at LightningClient.once.res (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:121:28)
    at Object.onceWrapper (events.js:286:20)
    at LightningClient.emit (events.js:198:13)
    at Interface.LightningClient.rl.on.line (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:76:17)
    at Interface.emit (events.js:198:13)
    at Interface._onLine (readline.js:308:10)
    at Interface._normalWrite (readline.js:451:12)
    at Socket.ondata (readline.js:165:10)
    at Socket.emit (events.js:198:13)
POST /rpc 500 14364.523 ms - -
POST /rpc 200 2.569 ms - 581
POST /rpc 200 2.289 ms - 581
POST /rpc 200 2.615 ms - -
POST /rpc 200 2.513 ms - 581
pay: FATAL SIGNAL 11 (version v0.9.0-44-g01a82d3)
0x55dd066064d0 send_backtrace
        common/daemon.c:38
0x55dd0660656a crashdump
        common/daemon.c:51
0x7f0468dd720f ???
        ???:0
0x7f0468e3e53e ???
        ???:0
0x55dd065f0b1f attempt_ongoing
        plugins/pay.c:1638
0x55dd065f0fc8 listsendpays_done
        plugins/pay.c:1820
0x55dd065f68a0 handle_rpc_reply
        plugins/libplugin.c:551
0x55dd065f698d rpc_read_response_one
        plugins/libplugin.c:666
0x55dd065f6a08 rpc_conn_read_response
        plugins/libplugin.c:685
0x55dd0661615a next_plan
        ccan/ccan/io/io.c:59
0x55dd06616605 do_plan
        ccan/ccan/io/io.c:407
0x55dd066166a2 io_ready
        ccan/ccan/io/io.c:417
0x55dd06617fe6 io_loop
        ccan/ccan/io/poll.c:445
0x55dd065f7543 plugin_main
        plugins/libplugin.c:1303
0x55dd065f4560 main
        plugins/pay.c:2063
0x7f0468db80b2 ???
        ???:0
0x55dd065efdfd ???
        ???:0
0xffffffffffffffff ???
        ???:0
Lightning client connection closed, reconnecting
Lightning client connection closed, reconnecting
Lightning client connection error { Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:396:12)
    at Promise (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:125:30)
    at new Promise (<anonymous>)
    at clientConnectionPromise.then (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:117:25)
    at process._tickCallback (internal/process/next_tick.js:68:7) code: 'EPIPE' }
Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:396:12)
    at Promise (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:125:30)
    at new Promise (<anonymous>)
    at clientConnectionPromise.then (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:117:25)
    at process._tickCallback (internal/process/next_tick.js:68:7)
POST /rpc 500 8.376 ms - 437
Lightning client connection error { Error: connect ECONNREFUSED /home/nate/.lightning/bitcoin/lightning-rpc
    at PipeConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '/home/nate/.lightning/bitcoin/lightning-rpc' }
uncaughtException, stopping process
Error: connect ECONNREFUSED /home/nate/.lightning/bitcoin/lightning-rpc
    at PipeConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)
nate@nates-server:~$

lightningd also goes down as well.

The same will happen after paying u/lntipbot. There does exist a valid path to u/lntipbot's node; it costs around 0.03 sat. for me to make the payment. However, spark-wallet will still die after making the payment, as will lightningd. Trying to run lightning-cli commands after this has happened will result in an error telling you:

lightning-cli: Connecting to 'lightning-rpc': Connection refused

...which indicates that lightningd is not running because if lightningd is started again, lightning-cli commands will work again.

bitcoind does not die, and will continue to run.

[shesek]

This seems to be a c-lightning issue not specifically related to Spark. Could you try making a payment directly with lightning-cli instead of through Spark's GUI to verify if that's the case?

[NateNate60]

Using lightning-cli does not appear to kill lightningd.

[shesek]

Are you still able to reproduce this with spark?

[NateNate60]

Yes, it still happens when using the Spark GUI.

[NateNate60]

I just did a clean install by using sudo npm -g remove spark-wallet and sudo npm -g install spark-wallet. It didn't fix the issue, but I'll continue to investigate. There's a fair chance that it may be down to user error and I'm just an idiot

[NateNate60]

I removed the config directory (~/.spark-wallet) to force it to create a new one, and the problem is still there. I'm now going to try re-installing c-lightning to see if it fixes the issue

EDIT: As I've found out it's not possible to back up c-lightning I won't be re-installing it

[shesek]

I'm not really sure what could be causing this to happen when paying via spark but not when paying directly, spark basically just calls pay <bolt11> internally.

Starting spark with --verbose (or -V) will print all the rpc requests being sent out and the their responses, this could help shed some light on what's happening there exactly.

[NateNate60]

Asterisks indicate redaction, not actual output

[Long list of invoices and other irrelevant junk before this]

POST /rpc 200 4.193 ms - 581
  clightning-client #5 --> decodepay [ 'lnbc200n1p0n********************************************************************************* ] +3s
  clightning-client #5 <-- { currency: 'bc',
  clightning-client   created_at: 1597376177,
  clightning-client   expiry: 1200,
  clightning-client   payee:
  clightning-client    '0219c2f8818b************************************',
  clightning-client   msatoshi: 20000,
  clightning-client   amount_msat: '20000msat',
  clightning-client   description: '2fcabc3d71fe4999a**************',
  clightning-client   min_final_cltv_expiry: 40,
  clightning-client   features: '',
  clightning-client   payment_hash:
  clightning-client    'f51fde1a884ad24547057d53baf9b3ae2b*********************',
  clightning-client   signature:
  clightning-client    '30440**********************************************************************************************' } +2ms
POST /rpc 200 4.368 ms - 502
  clightning-client #6 --> pay [ 'lnbc200n1p0n*********************************************************************************' ] +1s
  clightning-client #7 --> getinfo [] +4s
  clightning-client #7 <-- { id:
  clightning-client    '03bacbc1c*********************************************',
  clightning-client   alias: 'NateNate60\'s node',
  clightning-client   color: '03bacb',
  clightning-client   num_peers: 4,
  clightning-client   num_pending_channels: 0,
  clightning-client   num_active_channels: 4,
  clightning-client   num_inactive_channels: 0,
  clightning-client   address:
  clightning-client    [ { type: 'ipv6',
  clightning-client        address: '**********************',
  clightning-client        port: 9735 } ],
  clightning-client   binding:
  clightning-client    [ { type: 'ipv6', address: '::', port: 9735 },
  clightning-client      { type: 'ipv4', address: '0.0.0.0', port: 9735 } ],
  clightning-client   version: 'v0.9.0-44-g01a82d3',
  clightning-client   blockheight: 643618,
  clightning-client   network: 'bitcoin',
  clightning-client   msatoshi_fees_collected: 0,
  clightning-client   fees_collected_msat: '0msat',
  clightning-client   'lightning-dir': '/home/nate/.lightning/bitcoin' } +3ms
POST /rpc 200 5.266 ms - 581
  clightning-client #6 <-- { destination:
  clightning-client    '0219c2f881*********************************************',
  clightning-client   payment_hash:
  clightning-client    'f51fde1a8***********************************',
  clightning-client   created_at: 1597376189.642,
  clightning-client   parts: 1,
  clightning-client   msatoshi: 20000,
  clightning-client   amount_msat: '20000msat',
  clightning-client   msatoshi_sent: 20001,
  clightning-client   amount_sent_msat: '20001msat',
  clightning-client   payment_preimage:
  clightning-client    '87a9d73458*****************************************************',
  clightning-client   status: 'complete' } +2ms
POST /rpc 200 3576.298 ms - 406
  clightning-client #8 --> listpays [] +8s
pay: FATAL SIGNAL 11 (version v0.9.0-44-g01a82d3)
0x55c95d02a4d0 send_backtrace
        common/daemon.c:38
0x55c95d02a56a crashdump
        common/daemon.c:51
0x7f4450d5f20f ???
        ???:0
0x7f4450dc653e ???
        ???:0
0x55c95d014b1f attempt_ongoing
        plugins/pay.c:1638
0x55c95d014fc8 listsendpays_done
        plugins/pay.c:1820
0x55c95d01a8a0 handle_rpc_reply
        plugins/libplugin.c:551
0x55c95d01a98d rpc_read_response_one
        plugins/libplugin.c:666
0x55c95d01aa08 rpc_conn_read_response
        plugins/libplugin.c:685
0x55c95d03a15a next_plan
        ccan/ccan/io/io.c:59
0x55c95d03a605 do_plan
        ccan/ccan/io/io.c:407
0x55c95d03a6a2 io_ready
        ccan/ccan/io/io.c:417
0x55c95d03bfe6 io_loop
        ccan/ccan/io/poll.c:445
0x55c95d01b543 plugin_main
        plugins/libplugin.c:1303
0x55c95d018560 main
        plugins/pay.c:2063
0x7f4450d400b2 ???
        ???:0
0x55c95d013dfd ???
        ???:0
0xffffffffffffffff ???
        ???:0
Lightning client connection closed, reconnecting
Lightning client connection closed, reconnecting
  clightning-client #9 --> listpeers [] +2s
Lightning client connection error { Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:396:12)
    at Promise (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:125:30)
    at new Promise (<anonymous>)
    at clientConnectionPromise.then (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:117:25)
    at process._tickCallback (internal/process/next_tick.js:68:7) code: 'EPIPE' }
Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:396:12)
    at Promise (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:125:30)
    at new Promise (<anonymous>)
    at clientConnectionPromise.then (/usr/local/lib/node_modules/spark-wallet/node_modules/clightning-client/index.js:117:25)
    at process._tickCallback (internal/process/next_tick.js:68:7)
POST /rpc 500 4.258 ms - 437
  clightning-client Trying to reconnect... +342ms
  clightning-client Trying to reconnect... +1ms
Lightning client connection error { Error: connect ECONNREFUSED /home/nate/.lightning/bitcoin/lightning-rpc
    at PipeConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '/home/nate/.lightning/bitcoin/lightning-rpc' }
uncaughtException, stopping process
Error: connect ECONNREFUSED /home/nate/.lightning/bitcoin/lightning-rpc
    at PipeConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)
nate@nates-server:~$

[shesek]

It seems like the payment actually does go through, its the call to listpays after it that crashes everything.

I'll try to ask on the c-lightning IRC channel and see if anyone has any hints.

[shesek]

I managed to find the cause on the c-lightning tracker, its this bug: ElementsProject/lightning#3915

There already is a fix that was merged yesterday: ElementsProject/lightning#3927

So the next release should resolve this, but I'm not sure if there's a workaround that you could use in the meanwhile.

[NateNate60]

ElementsProject/lightning#3928 lists ElementsProject/lightning#3927 as one of the things that will be included in v0.9.0-1 of C-Lightning, which was released two days ago.

[shesek]

@NateNate60 Did you try upgrading? Does the issue persist?

[NateNate60]

Upgrading appears to fix the issue.

For those in the future who may stumble across this thread, just follow the install instructions for building from the source in ElementsProject/lightning, and it should work. The ~/.lightning folder won't be overwritten so your channels and funds will be saved.

[shesek]

Great, glad it worked out!