Funding channel causes crash due to "UNIQUE constraint failed: peers.node_id"

[sadilek]

I connected to a node and opened a channel:

$ lightning-cli listpeers | grep 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac
<empty, not connected to this node yet>
$ lightning-cli connect 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac 52.215.249.189 9735
{ "id" : "0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac" }
$ lightning-cli fundchannel 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac 50000
lightning-cli: reading response: Success

Lightningd crashed:

2018-02-18T23:43:21.033Z lightningd(17531): 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac chan #0: State changed from UNINITIALIZED to OPENINGD
wallet_channel_save: UNIQUE constraint failed: peers.node_id
2018-02-18T23:43:21.040Z lightningd(17531): wallet_channel_save: UNIQUE constraint failed: peers.node_id
Log dumped in crash.log
2018-02-18T23:43:21.849Z lightningd(17531): FATAL SIGNAL 6 RECEIVED
2018-02-18T23:43:21.861Z lightningd(17531): backtrace: lightningd/log.c:498 (log_crash) 0x411f92
2018-02-18T23:43:21.861Z lightningd(17531): backtrace: (null):0 ((null)) 0x7f351c4694af
2018-02-18T23:43:21.861Z lightningd(17531): backtrace: (null):0 ((null)) 0x7f351c469428
2018-02-18T23:43:21.861Z lightningd(17531): backtrace: (null):0 ((null)) 0x7f351c46b029
2018-02-18T23:43:21.861Z lightningd(17531): backtrace: lightningd/log.c:587 (fatal) 0x4123cc
2018-02-18T23:43:21.862Z lightningd(17531): backtrace: wallet/db.c:217 (db_exec_prepared_) 0x44e5dc
2018-02-18T23:43:21.862Z lightningd(17531): backtrace: wallet/wallet.c:800 (wallet_channel_save) 0x4535d3
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: lightningd/peer_control.c:2415 (peer_offer_channel) 0x420902
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: lightningd/peer_control.c:2492 (gossip_peer_released) 0x420d73
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: lightningd/subd.c:306 (sd_msg_reply) 0x4269e0
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: lightningd/subd.c:454 (sd_msg_read) 0x426fc5
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: lightningd/subd.c:327 (read_fds) 0x426add
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x45e440
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x45ef17
2018-02-18T23:43:21.863Z lightningd(17531): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x45ef55
2018-02-18T23:43:21.864Z lightningd(17531): backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x460824
2018-02-18T23:43:21.864Z lightningd(17531): backtrace: lightningd/lightningd.c:378 (main) 0x4106e6
2018-02-18T23:43:21.864Z lightningd(17531): backtrace: (null):0 ((null)) 0x7f351c45482f
2018-02-18T23:43:21.864Z lightningd(17531): backtrace: (null):0 ((null)) 0x4032d8
2018-02-18T23:43:21.864Z lightningd(17531): backtrace: (null):0 ((null)) 0xffffffffffffffff
Fatal signal 6. 0x412078 log_crash
        lightningd/log.c:524
0x7f351c4694af ???
        ???:0
0x7f351c469428 ???
        ???:0
0x7f351c46b029 ???
        ???:0
0x4123cc fatal
        lightningd/log.c:587
0x44e5dc db_exec_prepared_
        wallet/db.c:217
0x4535d3 wallet_channel_save
        wallet/wallet.c:800
0x420902 peer_offer_channel
        lightningd/peer_control.c:2415
0x420d73 gossip_peer_released
        lightningd/peer_control.c:2492
0x4269e0 sd_msg_reply
        lightningd/subd.c:306
0x426fc5 sd_msg_read
        lightningd/subd.c:454
0x426add read_fds
        lightningd/subd.c:327
0x45e440 next_plan
        ccan/ccan/io/io.c:59
0x45ef17 do_plan
        ccan/ccan/io/io.c:387
0x45ef55 io_ready
        ccan/ccan/io/io.c:397
0x460824 io_loop
        ccan/ccan/io/poll.c:310
0x4106e6 main
        lightningd/lightningd.c:378
0x7f351c45482f ???
        ???:0
0x4032d8 ???

By the time of the crash, my node was fully caught up. After the restart, it's now catching up again:

$ lightning-cli getinfo
{ "id" : "036487e0bd981617c674c2856fc0050472a0182838e0a4a1a67545c6cdee9f49a0", "port" : 9735, "address" : 
	[ 
		{ "type" : "ipv4", "address" : "81.6.40.158", "port" : 9735 } ], "version" : "v0.5.2-2016-11-21-1990-gb2819f9", "blockheight" : 507142, "network" : "bitcoin" }

I might have been connected to this node in the past. I happen to have a copy of the sqllite DB from before the crash.

$ sqlite3 /tmp/lightningd.sqlite3 
SQLite version 3.11.0 2016-02-15 17:29:24
Enter ".help" for usage hints.
sqlite> select id, hex(node_id), address from peers where hex(node_id) like "0333%";
102|0333B58F86A0C31DA7EE61A4BC2232FACCF8C4FE4167FE0DD9CE019FE03E82FAAC|52.215.249.189:9735

So despite listpeers not listing the node, it's still in the peers table. There is no channel referencing it though:
sqlite> select id, state from channels where hex(peer_id) like "0333%";

I can reproduce this, so let me know if you need more info.

[cdecker]

Thanks @sadilek for the detailed issue report. I think this is similar to (if not a duplicate of) #1000

[sadilek]

Indeed, sorry for missing that one. The issue seems to have been resolved for @Sjors after a dev-rescan-outputs. I can still reproduce it though. My node was caught up by now, and I ran this:

$ lightning-cli dev-rescan-outputs
<long output>
$ lightning-cli listpeers | grep 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac
$ sqlite3 .lightning/lightningd.sqlite3 
SQLite version 3.11.0 2016-02-15 17:29:24
Enter ".help" for usage hints.
sqlite> select id, hex(node_id), address from peers where hex(node_id) like "0333%";
102|0333B58F86A0C31DA7EE61A4BC2232FACCF8C4FE4167FE0DD9CE019FE03E82FAAC|52.215.249.189:9735
$ lightning-cli connect 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac 52.215.249.189 9735
{ "id" : "0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac" }
$ lightning-cli listpeers | grep 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac
		{ "state" : "GOSSIPING", "id" : "0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac", "netaddr" : 
$ lightning-cli fundchannel 0333b58f86a0c31da7ee61a4bc2232faccf8c4fe4167fe0dd9ce019fe03e82faac 50000
lightning-cli: reading response: Success

Node crashed with same error.

[rustyrussell]

Hmm, what state does the db say it's in?

select state, id, hex(node_id), address from peers where hex(node_id) like "0333%";

[cdecker]

@rustyrussell peers doesn't have a state, it's channels that have :-)

[sadilek]

@rustyrussell, still the same: There is an entry for the peer but no channel for it:

sqlite> select id, hex(node_id), address from peers where hex(node_id) like "0333%";
102|0333B58F86A0C31DA7EE61A4BC2232FACCF8C4FE4167FE0DD9CE019FE03E82FAAC|52.215.249.189:9735
sqlite> select id, state from channels where hex(peer_id) like "0333%";
<empty>

[windsok]

I also have this error, running commit e48a97f

This occurred while the node was unattended, so was not due to any direct action by me

+266177.212285888 lightningd(29959):INFO: 0211ad124eaecaf2b223bad2f5381e81b3639f2a652b5aa7a0ceffc8593931fc30 chan #0: State changed from UNINITIALIZED to OPENINGD
+266177.222512343 lightningd(29959):DEBUG: lightning_openingd-0211ad124eaecaf2b223bad2f5381e81b3639f2a652b5aa7a0ceffc8593931fc30 chan #0: pid 19977, msgfd 16
+266177.231419094 lightningd(29959):BROKEN: wallet_channel_save: UNIQUE constraint failed: peers.node_id
+266177.555645182 lightningd(29959):BROKEN: FATAL SIGNAL 6 RECEIVED
+266177.575493838 lightningd(29959):BROKEN: backtrace: lightningd/log.c:498 (log_crash) 0x411c09
+266177.575731844 lightningd(29959):BROKEN: backtrace: (null):0 ((null)) 0x7f1cc16ef4af
+266177.575859353 lightningd(29959):BROKEN: backtrace: (null):0 ((null)) 0x7f1cc16ef428
+266177.575961162 lightningd(29959):BROKEN: backtrace: (null):0 ((null)) 0x7f1cc16f1029
+266177.576056290 lightningd(29959):BROKEN: backtrace: lightningd/log.c:587 (fatal) 0x412043
+266177.576339176 lightningd(29959):BROKEN: backtrace: wallet/db.c:217 (db_exec_prepared_) 0x44d92e
+266177.576874386 lightningd(29959):BROKEN: backtrace: wallet/wallet.c:759 (wallet_channel_save) 0x452847
+266177.577675432 lightningd(29959):BROKEN: backtrace: lightningd/peer_control.c:2341 (peer_accept_channel) 0x41f92d
+266177.577886446 lightningd(29959):BROKEN: backtrace: lightningd/peer_control.c:506 (peer_sent_nongossip) 0x41a5d7
+266177.578221792 lightningd(29959):BROKEN: backtrace: lightningd/gossip_control.c:55 (peer_nongossip) 0x408d93
+266177.578343360 lightningd(29959):BROKEN: backtrace: lightningd/gossip_control.c:144 (gossip_msg) 0x408fed
+266177.578758345 lightningd(29959):BROKEN: backtrace: lightningd/subd.c:501 (sd_msg_read) 0x4264f3
+266177.578874828 lightningd(29959):BROKEN: backtrace: lightningd/subd.c:327 (read_fds) 0x425e32
+266177.579200967 lightningd(29959):BROKEN: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x45d44e
+266177.579371911 lightningd(29959):BROKEN: backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x45df25
+266177.579471708 lightningd(29959):BROKEN: backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x45df63
+266177.579698965 lightningd(29959):BROKEN: backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x45f832
+266177.579990511 lightningd(29959):BROKEN: backtrace: lightningd/lightningd.c:351 (main) 0x41035d
+266177.580097459 lightningd(29959):BROKEN: backtrace: (null):0 ((null)) 0x7f1cc16da82f
+266177.580189200 lightningd(29959):BROKEN: backtrace: (null):0 ((null)) 0x403248
+266177.580278106 lightningd(29959):BROKEN: backtrace: (null):0 ((null)) 0xffffffffffffffff

[windsok]

sqlite> select id, hex(node_id), address from peers where hex(node_id) like "0211ad%";
46|0211AD124EAECAF2B223BAD2F5381E81B3639F2A652B5AA7A0CEFFC8593931FC30|[::ffff:47.184.129.94]:48294
sqlite> select id, state from channels where hex(peer_id) like "0211ad%";
<empty>

[laanwj]

Same issue here, it happens reproducibly between two of my own nodes, which used to have a channel in the past. This channel was auto-closed due to unknown (to me) reasons. When I try to fundchannel a new channel from the one to the other node, on the connected-to node I get the error:

wallet_channel_insert: UNIQUE constraint failed: peers.node_id

Program received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f2cc7c7f3fa in __GI_abort () at abort.c:89
#2  0x0000556ecf2104ca in fatal (fmt=0x556ecf2aeea5 "%s: %s") at lightningd/log.c:592
#3  0x0000556ecf250fe1 in db_exec_prepared_ (caller=0x556ecf2b1ba0 <__func__.9071> "wallet_channel_insert", db=0x556ecf5a89c0, stmt=0x556ed0b292d8) at wallet/db.c:219
#4  0x0000556ecf2566ef in wallet_channel_insert (w=0x556ecf5a31a0, chan=0x556ed0b27770) at wallet/wallet.c:897
#5  0x0000556ecf21e298 in wallet_commit_channel (ld=0x556ecf5a2030, uc=0x556ed0b2fd80, remote_commit=0x556ed0b31100, remote_commit_sig=0x7fff34014870, funding_txid=0x7fff34014850, funding_outnum=1, 
    funding_satoshi=129845, push_msat=0, channel_flags=1 '\001', channel_info=0x7fff34014940, feerate=293) at lightningd/peer_control.c:2239
#6  0x0000556ecf21ee11 in opening_fundee_finished (openingd=0x556ed0b302f0, reply=0x556ed0b27260 <incomplete sequence \327>, fds=0x556ed0b306e0, uc=0x556ed0b2fd80) at lightningd/peer_control.c:2445
#7  0x0000556ecf225d10 in sd_msg_reply (conn=0x556ed0b305e0, sd=0x556ed0b302f0, sr=0x556ed0b30b50) at lightningd/subd.c:307
#8  0x0000556ecf2262cb in sd_msg_read (conn=0x556ed0b305e0, sd=0x556ed0b302f0) at lightningd/subd.c:435
#9  0x0000556ecf225e11 in read_fds (conn=0x556ed0b305e0, sd=0x556ed0b302f0) at lightningd/subd.c:328
#10 0x0000556ecf2615c5 in next_plan (conn=0x556ed0b305e0, plan=0x556ed0b30610) at ccan/ccan/io/io.c:59
#11 0x0000556ecf2620c2 in do_plan (conn=0x556ed0b305e0, plan=0x556ed0b30610, idle_on_epipe=false) at ccan/ccan/io/io.c:387
#12 0x0000556ecf262100 in io_ready (conn=0x556ed0b305e0, pollflags=1) at ccan/ccan/io/io.c:397
#13 0x0000556ecf263a4a in io_loop (timers=0x556ecf5a2120, expired=0x7fff34014d78) at ccan/ccan/io/poll.c:310
#14 0x0000556ecf20e71a in main (argc=9, argv=0x7fff34014ea8) at lightningd/lightningd.c:373

Same result as those above when trying with sqlite3: the peer is in the database, no channels.

[rustyrussell]

Thanks for all the reports. We now eliminate peers from db when no more channels. But we didn't always, so we can have old ones. Fix incoming... "Wladimir J. van der Laan" <notifications@github.com> writes:

…

Same issue here, it happens reproducibly between two of my own nodes, which used to have a channel in the past. This channel was auto-closed due to unknown (to me) reasons. When I try to fundchannel a new channel from the one to the other node, on the connected-to node I get the error: ``` wallet_channel_insert: UNIQUE constraint failed: peers.node_id Program received signal SIGABRT, Aborted. __GI_raise ***@***.***=6) at ../sysdeps/unix/sysv/linux/raise.c:51 51 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory. (gdb) bt #0 __GI_raise ***@***.***=6) at ../sysdeps/unix/sysv/linux/raise.c:51 #1 0x00007f2cc7c7f3fa in __GI_abort () at abort.c:89 #2 0x0000556ecf2104ca in fatal (fmt=0x556ecf2aeea5 "%s: %s") at lightningd/log.c:592 #3 0x0000556ecf250fe1 in db_exec_prepared_ (caller=0x556ecf2b1ba0 <__func__.9071> "wallet_channel_insert", db=0x556ecf5a89c0, stmt=0x556ed0b292d8) at wallet/db.c:219 #4 0x0000556ecf2566ef in wallet_channel_insert (w=0x556ecf5a31a0, chan=0x556ed0b27770) at wallet/wallet.c:897 #5 0x0000556ecf21e298 in wallet_commit_channel (ld=0x556ecf5a2030, uc=0x556ed0b2fd80, remote_commit=0x556ed0b31100, remote_commit_sig=0x7fff34014870, funding_txid=0x7fff34014850, funding_outnum=1, funding_satoshi=129845, push_msat=0, channel_flags=1 '\001', channel_info=0x7fff34014940, feerate=293) at lightningd/peer_control.c:2239 #6 0x0000556ecf21ee11 in opening_fundee_finished (openingd=0x556ed0b302f0, reply=0x556ed0b27260 <incomplete sequence \327>, fds=0x556ed0b306e0, uc=0x556ed0b2fd80) at lightningd/peer_control.c:2445 #7 0x0000556ecf225d10 in sd_msg_reply (conn=0x556ed0b305e0, sd=0x556ed0b302f0, sr=0x556ed0b30b50) at lightningd/subd.c:307 #8 0x0000556ecf2262cb in sd_msg_read (conn=0x556ed0b305e0, sd=0x556ed0b302f0) at lightningd/subd.c:435 #9 0x0000556ecf225e11 in read_fds (conn=0x556ed0b305e0, sd=0x556ed0b302f0) at lightningd/subd.c:328 #10 0x0000556ecf2615c5 in next_plan (conn=0x556ed0b305e0, plan=0x556ed0b30610) at ccan/ccan/io/io.c:59 #11 0x0000556ecf2620c2 in do_plan (conn=0x556ed0b305e0, plan=0x556ed0b30610, idle_on_epipe=false) at ccan/ccan/io/io.c:387 #12 0x0000556ecf262100 in io_ready (conn=0x556ed0b305e0, pollflags=1) at ccan/ccan/io/io.c:397 #13 0x0000556ecf263a4a in io_loop (timers=0x556ecf5a2120, expired=0x7fff34014d78) at ccan/ccan/io/poll.c:310 #14 0x0000556ecf20e71a in main (argc=9, argv=0x7fff34014ea8) at lightningd/lightningd.c:373 ``` Same result when trying with `sqlite3`: the peer is in the database, no channels. -- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: #1029 (comment)

[sadilek]

Thanks, I can confirm that this issue is fixed for me!