v0.11.1, crash in connectd

[btweenthebars]

Issue and Steps to Reproduce

I've been experiencing this crash for a while (every 3~ days) and I know another CLN 0.11.1 user that ran into it.

I think I started seeing it since upgrading from rc5 to 0.11

from console:

lightning_connectd: FATAL SIGNAL 6 (version v0.11.1)
0x556ec0ac8381 send_backtrace
	common/daemon.c:33
0x556ec0ac8429 crashdump
	common/daemon.c:46
0x7f60ee66f55f ???
	???:0
0x7f60ee6bc34c ???
	???:0
0x7f60ee66f4b7 ???
	???:0
0x7f60ee659533 ???
	???:0
0x556ec0b20179 call_error
	ccan/ccan/tal/tal.c:93
0x556ec0b2034a check_bounds
	ccan/ccan/tal/tal.c:165
0x556ec0b203a8 to_tal_hdr
	ccan/ccan/tal/tal.c:176
0x556ec0b20e1d tal_steal_
	ccan/ccan/tal/tal.c:498
0x556ec0ab4d6e retry_peer_connected
	connectd/connectd.c:225
0x556ec0b0ee93 next_plan
	ccan/ccan/io/io.c:59
0x556ec0b0fb7c io_do_always
	ccan/ccan/io/io.c:435
0x556ec0b11836 handle_always
	ccan/ccan/io/poll.c:304
0x556ec0b11b2b io_loop
	ccan/ccan/io/poll.c:385
0x556ec0aba611 main
	connectd/connectd.c:2158
0x7f60ee65a30f ???
	???:0
0x7f60ee65a3c0 ???
	???:0
0x556ec0ab08b4 ???
	???:0
0xffffffffffffffff ???
	???:0
lightning_connectd: FATAL SIGNAL (version v0.11.1)
0x556ec0ac8381 send_backtrace
	common/daemon.c:33
0x556ec0ad67bd status_failed
	common/status.c:221
0x556ec0ad6b1a status_backtrace_exit
	common/subdaemon.c:18
0x556ec0ac8432 crashdump
	common/daemon.c:49
0x7f60ee66f55f ???
	???:0
0x7f60ee6bc34c ???
	???:0
0x7f60ee66f4b7 ???
	???:0
0x7f60ee659533 ???
	???:0
0x556ec0b20179 call_error
	ccan/ccan/tal/tal.c:93
0x556ec0b2034a check_bounds
	ccan/ccan/tal/tal.c:165
0x556ec0b203a8 to_tal_hdr
	ccan/ccan/tal/tal.c:176
0x556ec0b20e1d tal_steal_
	ccan/ccan/tal/tal.c:498
0x556ec0ab4d6e retry_peer_connected
	connectd/connectd.c:225
0x556ec0b0ee93 next_plan
	ccan/ccan/io/io.c:59
0x556ec0b0fb7c io_do_always
	ccan/ccan/io/io.c:435
0x556ec0b11836 handle_always
	ccan/ccan/io/poll.c:304
0x556ec0b11b2b io_loop
	ccan/ccan/io/poll.c:385
0x556ec0aba611 main
	connectd/connectd.c:2158
0x7f60ee65a30f ???
	???:0
0x7f60ee65a3c0 ???
	???:0
0x556ec0ab08b4 ???
	???:0
0xffffffffffffffff ???
	???:0

from lnlog:

2022-05-21T22:13:08.401Z **BROKEN** connectd: FATAL SIGNAL 6 (version v0.11.1)
2022-05-21T22:13:08.401Z **BROKEN** connectd: backtrace: common/daemon.c:38 (send_backtrace) 0x556ec0ac83da
2022-05-21T22:13:08.401Z **BROKEN** connectd: backtrace: common/daemon.c:46 (crashdump) 0x556ec0ac8429
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee66f55f
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee6bc34c
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee66f4b7
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee659533
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:93 (call_error) 0x556ec0b20179
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:165 (check_bounds) 0x556ec0b2034a
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:176 (to_tal_hdr) 0x556ec0b203a8
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:498 (tal_steal_) 0x556ec0b20e1d
2022-05-21T22:13:08.402Z **BROKEN** connectd: backtrace: connectd/connectd.c:225 (retry_peer_connected) 0x556ec0ab4d6e
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x556ec0b0ee93
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: ccan/ccan/io/io.c:435 (io_do_always) 0x556ec0b0fb7c
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: ccan/ccan/io/poll.c:304 (handle_always) 0x556ec0b11836
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: ccan/ccan/io/poll.c:385 (io_loop) 0x556ec0b11b2b
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: connectd/connectd.c:2158 (main) 0x556ec0aba611
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee65a30f
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee65a3c0
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x556ec0ab08b4
2022-05-21T22:13:08.403Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0xffffffffffffffff
2022-05-21T22:13:08.404Z **BROKEN** connectd: FATAL SIGNAL (version v0.11.1)
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: common/daemon.c:38 (send_backtrace) 0x556ec0ac83da
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: common/status.c:221 (status_failed) 0x556ec0ad67bd
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: common/subdaemon.c:18 (status_backtrace_exit) 0x556ec0ad6b1a
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: common/daemon.c:49 (crashdump) 0x556ec0ac8432
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee66f55f
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee6bc34c
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee66f4b7
2022-05-21T22:13:08.404Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee659533
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:93 (call_error) 0x556ec0b20179
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:165 (check_bounds) 0x556ec0b2034a
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:176 (to_tal_hdr) 0x556ec0b203a8
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: ccan/ccan/tal/tal.c:498 (tal_steal_) 0x556ec0b20e1d
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: connectd/connectd.c:225 (retry_peer_connected) 0x556ec0ab4d6e
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x556ec0b0ee93
2022-05-21T22:13:08.405Z **BROKEN** connectd: backtrace: ccan/ccan/io/io.c:435 (io_do_always) 0x556ec0b0fb7c
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: ccan/ccan/io/poll.c:304 (handle_always) 0x556ec0b11836
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: ccan/ccan/io/poll.c:385 (io_loop) 0x556ec0b11b2b
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: connectd/connectd.c:2158 (main) 0x556ec0aba611
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee65a30f
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x7f60ee65a3c0
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0x556ec0ab08b4
2022-05-21T22:13:08.406Z **BROKEN** connectd: backtrace: (null):0 ((null)) 0xffffffffffffffff
2022-05-21T22:13:08.406Z **BROKEN** connectd: STATUS_FAIL_INTERNAL_ERROR: FATAL SIGNAL

getinfo output

"version": "v0.11.1"

[btweenthebars]

I have this crash and #5284 , every once in a few days so that's okay. I just put it under a while loop. But today I had to stop CLN to fix something for a couple times. Upon restarting, I got hit with this crash (#5282) with the chance of 50/50 . I got to pray for it to pass the initial connecting phase to my ~300 peers. Once survives that, it will last for while.

So I think it might have something to do with the overload of lightning_connectd or resource spike in machine ? I have 24G RAM and never really get close to it.

One more thought. It looks like the lightning_connectd get spawned as much as the number of peers all at once. I'm not sure if we have some queuing for peer connection, we should have, to prevent it from spiking resources of the machine

[heyambob]

got a new one today

double free or corruption (!prev)
lightning_connectd: FATAL SIGNAL 6 (version v0.11.1)
0x55e290327381 send_backtrace
	common/daemon.c:33
0x55e290327429 crashdump
	common/daemon.c:46
0x7f6de7aee55f ???
	???:0
0x7f6de7b3b34c ???
	???:0
0x7f6de7aee4b7 ???
	???:0
0x7f6de7ad8533 ???
	???:0
0x7f6de7b2f396 ???
	???:0
0x7f6de7b4533b ???
	???:0
0x7f6de7b4742b ???
	???:0
0x7f6de7b49be2 ???
	???:0
0x55e29037fb09 del_tree
	ccan/ccan/tal/tal.c:421
0x55e29037fdcd tal_free
	ccan/ccan/tal/tal.c:486
0x55e29033661f clean_tmpctx
	common/utils.c:172
0x55e29032759f daemon_poll
	common/daemon.c:87
0x55e290370c4c io_loop
	ccan/ccan/io/poll.c:420
0x55e290319611 main
	connectd/connectd.c:2158
0x7f6de7ad930f ???
	???:0
0x7f6de7ad93c0 ???
	???:0
0x55e29030f8b4 ???
	???:0
0xffffffffffffffff ???
	???:0
lightning_connectd: FATAL SIGNAL (version v0.11.1)
0x55e290327381 send_backtrace
	common/daemon.c:33
0x55e2903357bd status_failed
	common/status.c:221
0x55e290335b1a status_backtrace_exit
	common/subdaemon.c:18
0x55e290327432 crashdump
	common/daemon.c:49
0x7f6de7aee55f ???
	???:0
0x7f6de7b3b34c ???
	???:0
0x7f6de7aee4b7 ???
	???:0
0x7f6de7ad8533 ???
	???:0
0x7f6de7b2f396 ???
	???:0
0x7f6de7b4533b ???
	???:0
0x7f6de7b4742b ???
	???:0
0x7f6de7b49be2 ???
	???:0
0x55e29037fb09 del_tree
	ccan/ccan/tal/tal.c:421
0x55e29037fdcd tal_free
	ccan/ccan/tal/tal.c:486
0x55e29033661f clean_tmpctx
	common/utils.c:172
0x55e29032759f daemon_poll
	common/daemon.c:87
0x55e290370c4c io_loop
	ccan/ccan/io/poll.c:420
0x55e290319611 main
	connectd/connectd.c:2158
0x7f6de7ad930f ???
	???:0
0x7f6de7ad93c0 ???
	???:0
0x55e29030f8b4 ???
	???:0
0xffffffffffffffff ???
	???:0
lightningd: gossipd failed (exit status 2), exiting.
Lost connection to the RPC socket.Lost connection to the RPC socket.Lost connection to the RPC socket.


Lost connection to the RPC socket.
Lost connection to the RPC socket.Lost connection to the RPC socket.

Lost connection to the RPC socket.
Lost connection to the RPC socket.
Lost connection to the RPC socket.

[whitslack]

I couldn't keep 0.11.1 running for more than a few minutes until I reverted 1c495ca. Kept getting this crash:

lightning_connectd: FATAL SIGNAL (version 0.11.1-gentoo-r0)
0x564ae04aad6c send_backtrace
        common/daemon.c:33
0x564ae04b650a status_failed
        common/status.c:221
0x564ae04b6786 status_backtrace_exit
        common/subdaemon.c:18
0x564ae04aadfc crashdump
        common/daemon.c:49
0x7ff61a5aa4af ???
        /var/tmp/portage/sys-libs/glibc-2.35-r5/work/glibc-2.35/signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0
0x7ff61a5f5fac __pthread_kill_implementation
        /var/tmp/portage/sys-libs/glibc-2.35-r5/work/glibc-2.35/nptl/pthread_kill.c:44
0x7ff61a5aa411 __GI_raise
        ../sysdeps/posix/raise.c:26
0x7ff61a595468 __GI_abort
        /var/tmp/portage/sys-libs/glibc-2.35-r5/work/glibc-2.35/stdlib/abort.c:79
0x564ae049743d check_bounds
        ccan/ccan/tal/tal.c:165
0x564ae049743d to_tal_hdr
        ccan/ccan/tal/tal.c:174
0x564ae04f5553 tal_steal_
        ccan/ccan/tal/tal.c:498
0x564ae049f568 retry_peer_connected
        connectd/connectd.c:225
0x564ae04e3d50 next_plan
        ccan/ccan/io/io.c:59
0x564ae04e3d50 io_do_always
        ccan/ccan/io/io.c:435
0x564ae04e5a6b handle_always
        ccan/ccan/io/poll.c:304
0x564ae04e5a6b io_loop
        ccan/ccan/io/poll.c:385
0x564ae049795a main
        connectd/connectd.c:2158
0x7ff61a596209 __libc_start_call_main
        ../sysdeps/nptl/libc_start_call_main.h:58
0x7ff61a5962bb __libc_start_main_impl
        ../csu/libc-start.c:389
0x564ae0498cc0 ???
        ???:0
0xffffffffffffffff ???
        ???:0

I'll take a few spurious unilateral closures over consistently crashing, thank you.

[whitslack]

Reverting 1c495ca does allow my node to keep running, but lightning_connectd is pegging 100% CPU. It doesn't appear to be negatively impacting the connectivity of my node, but I'd really like it to stop cooking my CPU for no good reason.

[whitslack]

My node is remaining disconnected from more of its peers than it was before I upgraded from 0.10.2. I am wondering if connectd is not making any outbound connections. ☹️

[whitslack]

After studying the code for a while, here's the intended logic as I see it:

1. After a peer connects inbound to us and exchanges INIT messages (so we learn the peer's node ID), peer_connected is called to decide what to do next.
2. peer_connected checks whether the peer's node ID is already present in the peers hashtable. If it is, then peer_connected delegates to peer_reconnected. (Otherwise, go to step 11.)
3. peer_reconnected checks whether the peer's node ID is already present in the reconnections hashtable. If it is, then peer_reconnected removes the existing reconnection structure from the hashtable and frees it. (The destructor removes the reconnection structure from the hashtable again, but this does nothing since it has already been removed.)
4. peer_reconnected tells the master daemon to disconnect the existing peer connection.
5. peer_reconnected allocates a reconnection structure, populates it, and adds it to the reconnections hashtable.
6. peer_reconnected registers retry_peer_connected as a callback to be invoked, with a pointer to the reconnection structure as an argument, whenever io_wake is called for the address of the entry in the peers hashtable. This puts the incoming peer connection to sleep.
7. Later, when the existing peer connection has been closed, peer_conn_closed calls io_wake for the address of the entry in the peers hashtable and then frees the entry. (The destructor for the entry removes the entry from the hashtable.)
8. Now that the new peer connection has been awakened, retry_peer_connected is invoked, with a pointer to the reconnection structure passed as an argument.
9. retry_peer_connected reparents the reconnection structure to the temporary context so that it will be freed later when the I/O loop is idle.
10. retry_peer_connected delegates to peer_connected, passing the arguments that were saved in step 5.
11. peer_connected checks whether the peer's node ID is already present in the peers hashtable. Since the node ID was removed from the peers hashtable in step 7, it is no longer present, so peer_connected will proceed to set up the new connection, which includes calling new_peer, which adds the peer to the peers hashtable.

I'm suspicious of the following scenario:

1. We have an already established connection with a given peer.
2. A new connection comes in and identifies itself as the same peer. We allocate a reconnection structure, tell master to disconnect the existing connection, and go to sleep.
3. Before the existing connection can be disconnected, another new connection comes in and identifies itself as the same peer. We free the existing reconnection structure, allocate a new one, tell master to disconnect the existing connection (again), and go to sleep.
4. Now we have two sleeping connections, both sleeping on the same wake key (the address of the peer structure). One is registered with a callback whose argument is a pointer to a freed reconnection structure. The other is registered with a callback whose argument is a pointer to the current reconnection structure.
5. When the existing connection eventually gets closed, peer_conn_closed will wake up both new connections, but the retry_peer_connected callback for one of them will attempt to tal_steal a pointer to a freed reconnection structure. BOOM!

You really should never free an object while there is an outstanding callback registered to be invoked with an argument that is a pointer to that object. The simplest fix that I can see is simply not to free the existing reconnection structure in peer_reconnected but rather always to let the retry_peer_connected callback free the structure (by means of reparenting it to tmpctx). However, I suspect this would leak in the case that the callback is never invoked, such as if the new connection is closed before io_wake is called.

Why is the reconnection structure allocated as a child of daemon rather than as a child of conn? If it were the latter instead, then it would not leak in the case that the connection gets closed before the retry_peer_connected callback can be invoked.

Furthermore, why does the reconnections hashtable even exist? The only use of the reconnection structure is as an argument to the callback, and that pointer has to remain valid for as long as that callback is registered, so you can't free it when another reconnection comes in from the same peer (but instead must only free it after the callback has finished using it or after you know the callback will never be invoked), so there's no use for the hashtable at all.

I'll experiment tonight with removing the reconnections hashtable (and the troublesome call to tal_free in peer_reconnected) and parenting the reconnection structure to the connection instead of the daemon.

[whitslack]

So, that apparently didn't work. I wasn't able to stay connected to peers, and I lost a few channels to closures. I've gone back to v0.11.1 with 1c495ca reverted. EDIT: Well damn. I was seeing the same behavior with that version, so I'm running 7cef0ec again. Maybe I suffer a slew of closures every time I restart my node.

I wish I could go back to 0.10.2. 😢 It was stable, didn't cook my CPU, and used half the RAM that 0.11.1 uses. Also, my routing fee revenues have taken a nose dive since I upgraded to 0.11.1, probably because I'm disconnected from so many of my channel peers. EDIT: Actually, on 7cef0ec I seem to be holding connections to more peers than I was on v0.11.1 with 1c495ca reverted.

[whitslack]

The channels that I'm losing are logging errors of the form Peer permanent failure in CHANNELD_NORMAL: channeld: received ERROR error channel [(hex)]: internal error. Not a helpful error message.

[heyambob]

The channels that I'm losing are logging errors of the form Peer permanent failure in CHANNELD_NORMAL: channeld: received ERROR error channel [(hex)]: internal error. Not a helpful error message.

The internal error is a separate issue, but from what i've been observing it could be triggered by shaky connection (maybe when restarting & connectd goes crazy) according to lightningnetwork/lnd#6485 . It's just one of the causes of the "internal error"

you can go down the rabbit hole here: #5102

[whitslack]

My channel count seems to have mostly stabilized. (I am losing channels much less frequently now.) Maybe I've already shed all/most of the channels that I had had with peers that send "internal error" channel errors for no good reason. EDIT: Nope. It was just a brief lull in the action. The massacre continues.