Error message sanitization failure (use-after-free)

[Ulmo]

Issue and Steps to Reproduce

Crashing:

    2018-03-17T19:40:30.826Z lightningd(21673): 02a3a17effc394d27bc71b7f458cab02eeafef4eafd1e736583e40e66ebe98a3dd chan #138: Peer has reconnected, state CHANNELD_NORMAL
    2018-03-17T19:40:30.826Z lightningd(21673): FATAL SIGNAL 6 RECEIVED
    2018-03-17T19:40:30.838Z lightningd(21673): backtrace: lightningd/log.c:493 (log_crash) 0x4156be
    2018-03-17T19:40:30.838Z lightningd(21673): backtrace: (null):0 ((null)) 0x7f38ab89e4af
    2018-03-17T19:40:30.838Z lightningd(21673): backtrace: (null):0 ((null)) 0x7f38ab89e428
    2018-03-17T19:40:30.838Z lightningd(21673): backtrace: (null):0 ((null)) 0x7f38ab8a0029
    2018-03-17T19:40:30.839Z lightningd(21673): backtrace: ccan/ccan/tal/tal.c:98 (call_error) 0x46e7b6
    2018-03-17T19:40:30.839Z lightningd(21673): backtrace: ccan/ccan/tal/tal.c:170 (check_bounds) 0x46e973
    2018-03-17T19:40:30.839Z lightningd(21673): backtrace: ccan/ccan/tal/tal.c:181 (to_tal_hdr) 0x46e9d1
    2018-03-17T19:40:30.839Z lightningd(21673): backtrace: ccan/ccan/tal/tal.c:666 (tal_len) 0x46f953
    2018-03-17T19:40:30.839Z lightningd(21673): backtrace: wire/gen_peer_wire.c:70 (fromwire_error) 0x440644
    2018-03-17T19:40:30.840Z lightningd(21673): backtrace: common/wire_error.c:60 (sanitize_error) 0x437fe6
    2018-03-17T19:40:30.840Z lightningd(21673): backtrace: lightningd/peer_control.c:391 (peer_connected) 0x422b91
    2018-03-17T19:40:30.840Z lightningd(21673): backtrace: lightningd/gossip_control.c:157 (gossip_msg) 0x40bc97
    2018-03-17T19:40:30.841Z lightningd(21673): backtrace: lightningd/subd.c:504 (sd_msg_read) 0x42a233
    2018-03-17T19:40:30.841Z lightningd(21673): backtrace: lightningd/subd.c:330 (read_fds) 0x429b48
    2018-03-17T19:40:30.841Z lightningd(21673): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x462442
    2018-03-17T19:40:30.841Z lightningd(21673): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x462f19
    2018-03-17T19:40:30.841Z lightningd(21673): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x462f57
    2018-03-17T19:40:30.842Z lightningd(21673): backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x4648a1
    2018-03-17T19:40:30.842Z lightningd(21673): backtrace: lightningd/lightningd.c:400 (main) 0x413e6e
    2018-03-17T19:40:30.842Z lightningd(21673): backtrace: (null):0 ((null)) 0x7f38ab88982f
    2018-03-17T19:40:30.842Z lightningd(21673): backtrace: (null):0 ((null)) 0x403448
    2018-03-17T19:40:30.842Z lightningd(21673): backtrace: (null):0 ((null)) 0xffffffffffffffff

and again:

   2018-03-17T20:02:23.736Z lightningd(16796): 0219b7b9750c94bd47d2300505fc1de2b71b5d97807334340d4bc3835b5ca639c1 chan #136: Peer has reconnected, state CHANNELD_AWAITING_LOCKIN
    2018-03-17T20:02:23.737Z lightningd(16796): FATAL SIGNAL 6 RECEIVED
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: lightningd/log.c:493 (log_crash) 0x4156be
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: (null):0 ((null)) 0x7f98909384af
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: (null):0 ((null)) 0x7f9890938428
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: (null):0 ((null)) 0x7f989093a029
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: ccan/ccan/tal/tal.c:98 (call_error) 0x46e7b6
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: ccan/ccan/tal/tal.c:170 (check_bounds) 0x46e973
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: ccan/ccan/tal/tal.c:180 (to_tal_hdr) 0x46e9c1
    2018-03-17T20:02:23.743Z lightningd(16796): backtrace: ccan/ccan/tal/tal.c:666 (tal_len) 0x46f953
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: gossipd/gen_gossip_wire.c:845 (towire_gossipctl_hand_back_peer) 0x4497ec
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: lightningd/peer_control.c:392 (peer_connected) 0x422bdb
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: lightningd/gossip_control.c:157 (gossip_msg) 0x40bc97
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: lightningd/subd.c:504 (sd_msg_read) 0x42a233
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: lightningd/subd.c:330 (read_fds) 0x429b48
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x462442
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x462f19
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x462f57
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: ccan/ccan/io/poll.c:310 (io_loop) 0x4648a1
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: lightningd/lightningd.c:400 (main) 0x413e6e
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: (null):0 ((null)) 0x7f989092382f
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: (null):0 ((null)) 0x403448
    2018-03-17T20:02:23.744Z lightningd(16796): backtrace: (null):0 ((null)) 0xffffffffffffffff

getinfo output

"version" : "v0.5.2-2016-11-21-2350-g234d67d",

[Ulmo]

Now, I can't even go back to the previous working version:

    Refusing to migrate down from version 57 to 50

[ZmnSCPxj]

Yes, we refuse to downgrade databases, and database has changed significantly and will change significantly, sorry.

Point of crash is:

lightning/lightningd/peer_control.c

Lines 389 to 396 in 234d67d

	send_error:
	/* Hand back to gossipd, with an error packet. */
	connect_failed(ld, &id, sanitize_error(msg, error, NULL));
	msg = towire_gossipctl_hand_back_peer(msg, &id, &cs, gossip_index,
	error);
	subd_send_msg(ld->gossip, take(msg));
	subd_send_fd(ld->gossip, peer_fd);
	subd_send_fd(ld->gossip, gossip_fd);

Digging deeper, the error variable is somehow invalid and not NULL, which is why sanitize_error is crashing.

We can see "Peer has reconnected, state %s" in the log, which points to this code loading the error variable:

lightning/lightningd/peer_control.c

Lines 325 to 333 in 234d67d

	if (channel) {
	log_debug(channel->log, "Peer has reconnected, state %s",
	channel_state_name(channel));
	/* If we have a canned error, deliver it now. */
	if (channel->error) {
	error = channel->error;
	goto send_error;
	}

So channel->error is invalid and not NULL.

[ZmnSCPxj]

Hi Ulmo, #1237 has been merged in, which is likely a fix for this bug. Please confirm if you can encounter this bug again now that #1237 is merged in.

[ZmnSCPxj]

Closing, seems inactive, also as far as we can tell this has been fixed.