Crash due to channel->owner->name not being set

[Ulmo]

Issue and Steps to Reproduce

Here's a new crash. I issued a "lightning-cli listpeers" command and then it just crashed on me. It ran fine all day until I started looking at how it was doing.

log output:

2018-02-26T06:48:00.870Z lightningd(30620): 02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51 chan #3: Already have funding locked in
2018-02-26T06:48:00.889Z lightningd(30620): lightning_channeld-02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51 chan #3: init LOCAL: remote_per_commit = 03749477466256845a59bee52a6275b3f28344c1adc5af6fd11bb45041901c3956, old_remote_per_commit = 03af245c8249fa8a79ed529e68b3526de3c6d18b84119c6bec89c0a46dfcea79ba next_idx_local = 513 next_idx_remote = 513 revocations_received = 512 feerates 1616/1616 (range 428-14865)
2018-02-26T06:48:00.890Z lightningd(30620): lightning_channeld-02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51 chan #3: peer_out WIRE_CHANNEL_REESTABLISH
2018-02-26T06:48:01.158Z lightningd(30620): lightning_channeld-02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51 chan #3: Failed reading header: Connection reset by peer
2018-02-26T06:48:01.158Z lightningd(30620): lightning_channeld-02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51 chan #3: Peer connection lost
2018-02-26T06:48:01.158Z lightningd(30620): 02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51 chan #3: Peer transient failure in CHANNELD_SHUTTING_DOWN: lightning_channeld: Owning subdaemon lightning_channeld died (62208)
2018-02-26T06:48:01.158Z lightning_gossipd(30628): Forgetting remote peer 02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51
2018-02-26T06:48:01.159Z lightning_gossipd(30628): req: type WIRE_GOSSIPCTL_REACH_PEER len 35
2018-02-26T06:48:01.351Z lightning_gossipd(30628): Connected out for 02aeb693e2dfb2f890c65dcf27e6eb7d52dd3e4f7b74ce5fe646675793625f9b51
2018-02-26T06:48:01.351Z lightning_gossipd(30628): Initiator: Act 1
2018-02-26T06:48:01.351Z lightning_gossipd(30628): Initiator: Act 2
2018-02-26T06:48:01.542Z lightning_gossipd(30628): Initiator: Act 3
2018-02-26T06:48:01.542Z lightning_gossipd(30628): peer_out WIRE_INIT
2018-02-26T06:48:01.593Z lightningd(30620): Connected json input
2018-02-26T06:48:01.594Z lightning_gossipd(30628): req: type WIRE_GOSSIP_GETPEERS_REQUEST len 4
2018-02-26T06:48:01.594Z lightning_gossipd(30628): REPLY WIRE_GOSSIP_GETPEERS_REPLY with 0 fds
2018-02-26T06:48:01.595Z lightningd(30620): FATAL SIGNAL 11 RECEIVED
2018-02-26T06:48:01.609Z lightningd(30620): backtrace: lightningd/log.c:504 (log_crash) 0x414781
2018-02-26T06:48:01.609Z lightningd(30620): backtrace: (null):0 ((null)) 0x7f542b9d24af
2018-02-26T06:48:01.610Z lightningd(30620): backtrace: (null):0 ((null)) 0x7f542ba28746
2018-02-26T06:48:01.610Z lightningd(30620): backtrace: ccan/ccan/tal/str/str.c:18 (tal_strdup) 0x46d454
2018-02-26T06:48:01.610Z lightningd(30620): backtrace: common/json.c:436 (json_add_string) 0x432215
2018-02-26T06:48:01.610Z lightningd(30620): backtrace: lightningd/peer_control.c:633 (gossipd_getpeers_complete) 0x4216cb
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: lightningd/subd.c:311 (sd_msg_reply) 0x427a90
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: lightningd/subd.c:451 (sd_msg_read) 0x428063
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x461e9f
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x462976
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x4629b4
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x464283
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: lightningd/lightningd.c:403 (main) 0x412e85
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: (null):0 ((null)) 0x7f542b9bd82f
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: (null):0 ((null)) 0x403318
2018-02-26T06:48:01.611Z lightningd(30620): backtrace: (null):0 ((null)) 0xffffffffffffffff

getinfo output

Here's my version number:

2018-02-25T21:09:38.750Z lightningd(30620): Server started with public key 031c527494f295220d26a1814c18e7db3f4f03203ce1a53a0b74b52ed570a3972a, alias Plasma???Genesis (color #031c52) and lightningd v0.5.2-2016-11-21-2102-g160f9b0

[Ulmo]

That last bit of log entries was with "VIOLENTROUTE" again. I decided to finally screen its IP# from my host, to see if that prevents problems for a while.

[cdecker]

Seems to be a dangling owner pointer:

lightning/lightningd/peer_control.c

Lines 632 to 634 in fd4a36e

	if (channel->owner)
	json_add_string(response, "owner",
	channel->owner->name);

EDIT: more likely name is not setup (yet?), since we actually fail when attempting to access that.

[rustyrussell]

This one is weird.

name is always set in the subd constructor, and is in fact a string literal in all cases. I just audited owner, to make sure it's not a dangling pointer, and we always set it to NULL on freeing the subdaemon.

Any chance 'make clean && make' fixes it? I wonder if we've gotten out of sync somehow. I'm going to start running a permanent node under valgrind I think.

[ZmnSCPxj]

When a new_subd is created, it sets up a destructor destroy_subd. If destroy_subd is called and the subd has a channel field, it calls the errcb. However, the main errcb I have seen is channel_errmsg. This functions does not clear the owner field of the channel.

What happens when a subd dies for no good reason? It destroys the connection. However new_subd itself parents the subd to the connection. So destroying the connection also frees the subd. But this only calls the errcb without necessarily clearing the owner field of the channel the subd is attached to. Could this be the root cause?

[rustyrussell]

channel_errmsg calls either channel_fail_transient or channel_fail_permanent.

Both of those call channel_set_owner(channel, NULL) which unsets the owner field.

[ZmnSCPxj]

That is correct.... hmm, no further ideas on why this is segfaulting.

[Ulmo]

Looks like I did not do make clean. Here's the dates of all the .o files (possible for me to know since I save every build and every log file):

no_make_clean.txt

From now on, I will make clean. I usually did, but not always.

[cdecker]

PR #1164 was just merged, which should fix this issue. @Ulmo could you update and see if this error still occurs?