Crash while funding channel to previously connected node

[Sjors]

I reconnected to a node that (if I remember correctly) I was connected with in the past and had a channel with.

2018-02-14T15:28:33.994Z lightningd(4314): 023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028 chan #0: State changed from UNINITIALIZED to OPENINGD
2018-02-14T15:28:33.996Z lightningd(4314): lightning_openingd-023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028 chan #0: pid 7090, msgfd 21
2018-02-14T15:28:33.997Z lightningd(4314): wallet_channel_save: UNIQUE constraint failed: peers.node_id
2018-02-14T15:28:33.997Z lightningd(4314): FATAL SIGNAL 6 RECEIVED
2018-02-14T15:28:34.005Z lightningd(4314): backtrace: lightningd/log.c:498 (log_crash) 0x55a88d8ad860
2018-02-14T15:28:34.005Z lightningd(4314): backtrace: (null):0 ((null)) 0x7f9c8bb0b13f
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: (null):0 ((null)) 0x7f9c8bb0b0bb
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: (null):0 ((null)) 0x7f9c8bb0cf5c
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/log.c:587 (fatal) 0x55a88d8adcb6
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: wallet/db.c:217 (db_exec_prepared_) 0x55a88d8ea585
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: wallet/wallet.c:759 (wallet_channel_save) 0x55a88d8ef664
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/peer_control.c:2415 (peer_offer_channel) 0x55a88d8bbec4
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/peer_control.c:2492 (gossip_peer_released) 0x55a88d8bc348
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/subd.c:306 (sd_msg_reply) 0x55a88d8c213d
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/subd.c:454 (sd_msg_read) 0x55a88d8c2755
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/subd.c:327 (read_fds) 0x55a88d8c223e
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x55a88d8fa4b7
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x55a88d8fafb4
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x55a88d8faff2
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x55a88d8fc93c
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: lightningd/lightningd.c:351 (main) 0x55a88d8abf22
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: (null):0 ((null)) 0x7f9c8baf51c0
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: (null):0 ((null)) 0x55a88d89ea29
2018-02-14T15:28:34.006Z lightningd(4314): backtrace: (null):0 ((null)) 0xffffffffffffffff

In addition, listfunds now shows an empty outputs,, but there's no new channel under listchannels. I also don't think there was an on chain transaction, but not sure.

[Sjors]

According to the logs, I indeed had a channel with that node. I attached all
log entries relevant to this node.

Looks like the channel was closed yesterday:

2018-02-13T11:26:29.691Z lightningd(21780): peer 023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028: State changed from CHANNELD_NORMAL to FUNDING_SPEND_SEEN
2018-02-13T11:26:29.694Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): pid 12595, msgfd 17
2018-02-13T11:26:29.793Z lightningd(21780): peer 023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028: Got depth change 0->1 for 5e4bde1afbc25e2989de7b6a5fcc6a800b8f593387a74753dad85116721ccf7e
2018-02-13T11:26:29.798Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): Tracking output 0 of a0e5b53a759448ac771968fa40e524b3352951af2f9051b84c735bcd27d01fd3: FUNDING_TRANSACTION/FUNDING_OUTPUT
2018-02-13T11:26:29.798Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): Remote per-commit point: 02fd368ea03e4a81ee6a3e5d28a38fcb3e17e1a8782ad951e4424cd25e0003bbc7
2018-02-13T11:26:29.798Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): Old remote per-commit point: 0213922314c2d65ffd3906f03008eef3db6241f05db50c704bbea049e22c4edb06
2018-02-13T11:26:29.798Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): commitnum = 492, revocations_received = 492
2018-02-13T11:26:29.798Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): Their unilateral tx, old commit point
2018-02-13T11:26:29.798Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): UPDATE WIRE_ONCHAIN_INIT_REPLY
2018-02-13T11:26:29.798Z lightningd(21780): peer 023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028: State changed from FUNDING_SPEND_SEEN to ONCHAIND_THEIR_UNILATERAL
2018-02-13T11:26:29.805Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): Initial feerate 0 to 11551
2018-02-13T11:26:29.809Z lightningd(21780): lightning_onchaind(023d280ae29f84dcfd289eb66b57227fea3a7bde97ec2869923d3c4d5c6a426028): Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by THEIR_UNILATERAL (5e4bde1afbc25e2989de7b6a5fcc6a800b8f593387a74753dad85116721ccf7e)

[Sjors]

I also don't think there was an on chain transaction, but not sure.

There wasn't. I found the output that listfunds showed before this crash and now no longer shows. They're unspent on the blockchain. How do I make c-lightning aware of those funds again?

[cdecker]

You can use dev-rescan-outputs to sync the output state with bitcoind again, I wonder why it wasn't loading the peer from the DB.

[Sjors]

dev-rescan-outputs made the funds reappear. Also, I was able to reconnect to the node and successfully open a channel this time.

[Ulmo]

I'm getting crashes every hour or so. I can't see a lot of commonalities. Here's the last one:
https://gist.github.com/cdecker/df9ec4174516744110aef7ff374aa2ae#file-gistfile1-txt

Here's the penultimate one:
https://gist.github.com/cdecker/df9ec4174516744110aef7ff374aa2ae#file-gistfile2-txt

And the previous:
https://gist.github.com/cdecker/df9ec4174516744110aef7ff374aa2ae#file-gistfile3-txt

And so on. Here's a summary, with "egrep -B4 -A2 FATAL log.29056.0":
https://gist.github.com/cdecker/df9ec4174516744110aef7ff374aa2ae#file-gistfile4-txt

Here's a longer context grep:
https://gist.github.com/cdecker/df9ec4174516744110aef7ff374aa2ae#file-gistfile5-txt

Edit by @cdecker: I moved the lengthy logs to gist since they were utterly unreadable in their previous form.

[cdecker]

@Ulmo: that daemon seems to be utterly broken, failing even on log writes. Please update to latest master, perform a make distclean default check to have a clean build and verify that the integration tests pass. Then start the daemon with --dev-no-reconnect, close or dev-fail all channels, wait for them to be settled, then withdraw [btcaddr] all to another wallet and wipe the lightning-dir.