Invaid ERROR message AND unknown message type [49241]

[Ulmo]

Issue and Steps to Reproduce

Here's my log from my LND and C-Lightning nodes when I tried to connect from my C-Lightning node to my LND lightning node: I tried to sort it for time, but I can't figure out the timing of it at all, so I'm leaving them seperate:

    C-LN 2018-03-17T21:31:55.482Z lightningd(24002): Connected json input
    C-LN 2018-03-17T21:31:55.482Z lightning_gossipd(24020): req: type WIRE_GOSSIPCTL_PEER_ADDRHINT len 42
    C-LN 2018-03-17T21:31:55.483Z lightning_gossipd(24020): req: type WIRE_GOSSIPCTL_REACH_PEER len 35
    C-LN 2018-03-17T21:31:55.483Z lightning_gossipd(24020): Connected out for 03b1be68b8f564fe53f5456cf4bec901ba968fb72ed7291279ab0c87e0d22f1f49
    C-LN 2018-03-17T21:31:55.485Z lightning_gossipd(24020): peer_out WIRE_INIT
    C-LN 2018-03-17T21:31:55.486Z lightning_gossipd(24020): peer_in WIRE_INIT
    C-LN 2018-03-17T21:31:55.486Z lightning_gossipd(24020): UPDATE WIRE_GOSSIP_PEER_CONNECTED
    C-LN 2018-03-17T21:31:55.486Z lightning_gossipd(24020): UPDATE WIRE_GOSSIP_PEER_CONNECTED
    C-LN 2018-03-17T21:31:55.486Z lightningd(24002): 03b1be68b8f564fe53f5456cf4bec901ba968fb72ed7291279ab0c87e0d22f1f49 chan #149: Peer has reconnected, state CHANNELD_AWAITING_LOCKIN
    C-LN 2018-03-17T21:31:55.486Z lightningd(24002):jcon fd 16: Failing: Invalid ERROR message 'c059680300000000c0225e03000000000389ad5a000000000fd2a1150000000002000000000000000079ec0100000000f0e5e402000000000000000000000000'
    C-LN 2018-03-17T21:31:55.487Z lightning_gossipd(24020): req: type WIRE_GOSSIPCTL_HAND_BACK_PEER len 253
    C-LN 2018-03-17T21:31:55.487Z lightning_gossipd(24020): hand_back_peer 03b1be68b8f564fe53f5456cf4bec901ba968fb72ed7291279ab0c87e0d22f1f49: now local again
    C-LN 2018-03-17T21:31:55.487Z lightning_gossipd(24020): peer_out INVALID 49241
    
    LND 2018-03-17 14:31:55.486 [INF] SRVR: New inbound connection from 127.0.0.1:45794
    LND 2018-03-17 14:31:55.486 [DBG] PEER: Sending Init to 127.0.0.1:45794
    LND 2018-03-17 14:31:55.486 [DBG] PEER: Received Init from 127.0.0.1:45794
    LND 2018-03-17 14:31:55.486 [DBG] PEER: Loaded 0 active channels from database with NodeKey(031c527494f295220d26a1814c18e7db3f4f03203ce1a53a0b74b52ed570a3972a)
    LND 2018-03-17 14:31:55.487 [INF] PEER: unable to read message from 127.0.0.1:45794: unknown message type [49241]
    LND 2018-03-17 14:31:55.487 [DBG] SRVR: Peer 127.0.0.1:45794 has been disconnected

getinfo output

"v0.5.2-2016-11-21-2350-g234d67d"

[ZmnSCPxj]

This, and #1235, may have the same root cause, as both are related to channel->error variable.

Here, we grab channel->error and put it into an error variable, in the function peer_sent_nongossip:

lightning/lightningd/peer_control.c

Lines 451 to 458 in 234d67d

	if (peer && channel_id) {
	struct channel *channel;
	channel = channel_by_channel_id(peer, channel_id);
	if (channel && channel->error) {
	error = channel->error;
	goto send_error;
	}
	}

However, going to the send_error label:

lightning/lightningd/peer_control.c

Lines 465 to 472 in 234d67d

	send_error:
	/* Hand back to gossipd, with an error packet. */
	connect_failed(ld, id, sanitize_error(error, error, NULL));
	msg = towire_gossipctl_hand_back_peer(ld, 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);
	tal_free(error);

We free the error variable. But note that there is the possibility that error was actually the channel->error variable, and we have freed it but the channel->error variable refers to the same (already freed) memory.

[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, since inactive, also, as far as we can tell this has been fixed.