Crash while syncing

[pooleja]

As the lightning client is trying to catch back up with the latest, it is crashing every time when it gets up to a certain block. It then restarts the syncing process when it is restarted but always crashes when it gets back to the block causing it crash.

+11561.302910966 lightningd(8967):DEBUG: Adding block 509671: 0000000000000000003f7706874868a891ac277865a2d2ff5ce1f7f7b31a4bb6
+11563.805345009 lightningd(8967):DEBUG: Adding block 509672: 0000000000000000001ff145d1a56e65629e9d7b61f2790fa2e3a0c1cac083a2
+11564.552017161 lightningd(8967):UNUSUAL: 028501e256154aa4aa513acfc1ca498ae3e9f1a305f5c79ec0918b67ebbc78a796 chan #35: Peer permanent failure in ONCHAIN: Funding transaction spent (tx 18e198b6b15c4240465619a10e24668c7bd7171ee759ac34936393dec363afc6)
+11564.552307909 lightningd(8967):DEBUG: sendrawtransaction: 02000000000101d20f64c023c87c4b1b65e682642f69ba9344841a2d9f8d51ddf2d9d51f9c36a4000000000095f20880010b08030000000000220020dd59b9c27b3ce3ddbd8d5f2095409fdf914d2cc2a4bf3e6c7f0007ee8d69c81204004730440220113039df2a72cff2c0efd73f25c8e7e9f472ce7b0ec9ae2643aed8448e42b2470220166fe4eed371d6e47ccd515ba0f1b81c39be7683aa9036b0a4ae11d8f407ed340147304402205d7fa7b7662bce54993cf45db12bdc50d06482f5b08ffca4f0be19c14950dc1f022035e2b61910a1151c0d7f41e6611a92d81dc071e1af8f88c42eab93ea66abb41e01475221020bd964c24501599a31d6a630ace7b2ea05b6ac9a3ac67c87b9bb0837ac37621221021b6f31bef4d6ea65c41e8d58fb640a0bda0a41030fa5063e1d1552056b7aefd052aece6a8620
+11564.552854133 lightningd(8967):INFO: 028501e256154aa4aa513acfc1ca498ae3e9f1a305f5c79ec0918b67ebbc78a796 chan #35: State changed from ONCHAIN to FUNDING_SPEND_SEEN
+11565.014254700 lightningd(8967):DEBUG: sendrawtx exit 25, gave error code: -25?error message:?Missing inputs?
+11565.014815446 lightning_gossipd(8976):DEBUG: req: type WIRE_GOSSIP_DISABLE_CHANNEL len 12
+11565.014851136 lightning_gossipd(8976):DEBUG: Unable to find channel 505922:1405:0
+11565.015227486 lightningd(8967):INFO: 028501e256154aa4aa513acfc1ca498ae3e9f1a305f5c79ec0918b67ebbc78a796 chan #35: State changed from FUNDING_SPEND_SEEN to ONCHAIN
+11565.020482308 lightningd(8967):BROKEN: FATAL SIGNAL 11 RECEIVED
+11565.049999563 lightningd(8967):BROKEN: backtrace: lightningd/log.c:504 (log_crash) 0x415844
+11565.050033910 lightningd(8967):BROKEN: backtrace: (null):0 ((null)) 0x7f3dca50f4af
+11565.050149959 lightningd(8967):BROKEN: backtrace: lightningd/pay.c:389 (payment_failed) 0x41e4b0
+11565.050355671 lightningd(8967):BROKEN: backtrace: lightningd/peer_htlcs.c:812 (onchain_failed_our_htlc) 0x426234
+11565.050427532 lightningd(8967):BROKEN: backtrace: lightningd/onchain_control.c:184 (handle_missing_htlc_output) 0x41779b
+11565.050433479 lightningd(8967):BROKEN: backtrace: lightningd/onchain_control.c:265 (onchain_msg) 0x417ac9
+11565.050554767 lightningd(8967):BROKEN: backtrace: lightningd/subd.c:509 (sd_msg_read) 0x42990d
+11565.050620670 lightningd(8967):BROKEN: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x4617ef
+11565.050628969 lightningd(8967):BROKEN: backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x4622c6
+11565.050633990 lightningd(8967):BROKEN: backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x462304
+11565.050685924 lightningd(8967):BROKEN: backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x463c4e
+11565.050760153 lightningd(8967):BROKEN: backtrace: lightningd/lightningd.c:405 (main) 0x413f48
+11565.050765349 lightningd(8967):BROKEN: backtrace: (null):0 ((null)) 0x7f3dca4fa82f
+11565.050769023 lightningd(8967):BROKEN: backtrace: (null):0 ((null)) 0x403448
+11565.050772261 lightningd(8967):BROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff

[cdecker]

This was reported before in #1114 and got mixed up in the fix #1171, but seems this really is a distinct issue.

For reference the failing check is this

lightning/lightningd/pay.c

Lines 385 to 398 in dace9bf

	/* FIXME: Prior to 299b280f7, we didn't put route_nodes and
	* route_channels in db. If this happens, it's an old payment,
	* so we can simply mark it failed in db and return. */
	if (!payment->route_channels) {
	log_unusual(hout->key.channel->log,
	"No route_channels for htlc %s:"
	" was this an old database?",
	type_to_string(ltmp, struct sha256,
	&hout->payment_hash));
	wallet_payment_set_status(ld->wallet, &hout->payment_hash,
	PAYMENT_FAILED, NULL);
	tal_free(tmpctx);
	return;
	}

I'll just add @ZmnSCPxj's request for more information here:

We need to determine what payment is here. Can you run under gdb and inform us content of payment at this point when it crashes?

If payment is NULL then it means we have a database inconsistency --- we saved the HTLC but not the payment that triggered the creation of the HTLC.

[pooleja]

My gdb skillz are a little behind the curve... can you let me know what I should look for? I do see payment as being null.

2018-03-13T23:11:53.351Z lightningd(16548): 028501e256154aa4aa513acfc1ca498ae3e9f1a305f5c79ec0918b67ebbc78a796 chan #35: State changed from ONCHAIN to FUNDING_SPEND_SEEN
2018-03-13T23:11:53.822Z lightningd(16548): 028501e256154aa4aa513acfc1ca498ae3e9f1a305f5c79ec0918b67ebbc78a796 chan #35: State changed from FUNDING_SPEND_SEEN to ONCHAIN

Program received signal SIGSEGV, Segmentation fault.
0x000000000041e4b0 in payment_failed (ld=0x6e8030, hout=0x9f41c0, localfail=0x227e2a0 "WIRE_PERMANENT_CHANNEL_FAILURE: missing in commitment tx") at lightningd/pay.c:389
389             if (!payment->route_channels) {

also

(gdb) info args
...
payment = 0x0
...

[rustyrussell]

Yes, this looks like a db inconsistency, somehow. Cool bug!

Any chance you can email me the db at rusty@rustcorp.com.au ? It will compromise your privacy, but I can't steal your funds. I should at least be able to repair it for you, even if I can't figure the root cause.

[ZmnSCPxj]

Thank you @pooleja, that is precisely what is needed.

Assuming this is a bug symptom of old code that has since been fixed (hopefully), we could just add a protecting if (!payment) return; inside #ifdef COMPAT_V052. If it is not, though...

Can you inform us when you started using c-lightning, and how often (approximately) you have updated the code? Better would be a log of commit versions you have ever run but it is unlikely and unreasonable to ask for that (but if you do have that information...).

[pooleja]

I started running the node on Jan 20th (or thereabouts). I don't have the list of commits I have used :( But I have probably synced up to master around 5 times or so since then.

[pooleja]

@rustyrussell I emailed you. I am happy to trade some privacy for getting our node back up.

[rustyrussell]

OK, I had a brainwave yesterday, and I've just reproduced this.

It's not that we didn't create the payment in the db, it's that we deleted it when he retried a payment. That's almost certainly a mistake. PR incoming...