patch bad-gossip-debug.patch

connectd/connectd.c

@@ -49,6 +49,7 @@
 #include <sys/types.h>
 #include <sys/wait.h>
 #include <unistd.h>
+#include <wire/peer_wire.h>
 #include <wire/wire_io.h>
 #include <wire/wire_sync.h>
 
@@ -1851,8 +1852,11 @@ static void peer_send_msg(struct io_conn *conn,
 	/* This can happen if peer hung up on us (or wrong counter
 	 * if it reconnected). */
 	peer = peer_htable_get(daemon->peers, &id);
-	if (peer && peer->counter == counter)
+	if (peer && peer->counter == counter) {
+		status_debug("Sending %s from lightningd",
+			     peer_wire_name(fromwire_peektype(sendmsg)));
 		inject_peer_msg(peer, take(sendmsg));
+	}
 }
 
 static void dev_connect_memleak(struct daemon *daemon, const u8 *msg)
@@ -2175,8 +2179,11 @@ static struct io_plan *recv_gossip(struct io_conn *conn,
 			      fromwire_peektype(msg));
 
 	peer = peer_htable_get(daemon->peers, &dst);
-	if (peer)
+	if (peer) {
+		status_debug("Sending %s from gossipd",
+			     peer_wire_name(fromwire_peektype(gossip_msg)));
 		inject_peer_msg(peer, take(gossip_msg));
+	}
 
 	return daemon_conn_read_next(conn, daemon->gossipd);
 }

connectd/multiplex.c

@@ -514,9 +514,15 @@ static u8 *maybe_from_gossip_store(const tal_t *ctx, struct peer *peer)
 	/* Don't send back gossip they sent to us! */
 	if (msg) {
 		if (gossip_rcvd_filter_del(peer->gs.grf, msg)) {
+			status_peer_debug(&peer->id, "Gossip filter %s from gossip_store (next off = %zu)",
+					  peer_wire_name(fromwire_peektype(msg)),
+					  peer->gs.off);
 			msg = tal_free(msg);
 			goto again;
 		}
+		status_peer_debug(&peer->id, "Sending %s from gossip_store (next off = %zu)",
+				  peer_wire_name(fromwire_peektype(msg)),
+				  peer->gs.off);
 		status_peer_io(LOG_IO_OUT, &peer->id, msg);
 		return msg;
 	}
@@ -581,8 +587,11 @@ void send_custommsg(struct daemon *daemon, const u8 *msg)
 
 	/* Races can happen: this might be gone by now. */
 	peer = peer_htable_get(daemon->peers, &id);
-	if (peer)
+	if (peer) {
+		status_debug("Sending %s from custommsg",
+			     peer_wire_name(fromwire_peektype(custommsg)));
 		inject_peer_msg(peer, take(custommsg));
+	}
 }
 
 static void handle_ping_in(struct peer *peer, const u8 *msg)
@@ -693,15 +702,18 @@ static void handle_gossip_timestamp_filter_in(struct peer *peer, const u8 *msg)
 	 */
 	/* For us, this means we only sweep the gossip store for messages
 	 * if the first_timestamp is 0 */
-	if (first_timestamp == 0)
+	if (first_timestamp == 0) {
 		peer->gs.off = 1;
-	else if (first_timestamp == 0xFFFFFFFF)
+		status_peer_debug(&peer->id, "gossip_store zero timestamp off = %zu", peer->gs.off);
+	} else if (first_timestamp == 0xFFFFFFFF) {
 		peer->gs.off = peer->daemon->gossip_store_end;
-	else {
+		status_peer_debug(&peer->id, "gossip_store inf timestamp off = %zu", peer->gs.off);
+	} else {
 		/* We are actually a bit nicer than the spec, and we include
 		 * "recent" gossip here. */
 		update_recent_timestamp(peer->daemon);
 		peer->gs.off = peer->daemon->gossip_store_recent_off;
+		status_peer_debug(&peer->id, "gossip_store other timestamp off = %zu", peer->gs.off);
 	}
 
 	/* BOLT #7:
@@ -759,6 +771,8 @@ static bool handle_message_locally(struct peer *peer, const u8 *msg)
 
 	/* We remember these so we don't rexmit them */
 	gossip_rcvd_filter_add(peer->gs.grf, msg);
+	status_peer_debug(&peer->id, "Gossip filter adding %s",
+			  peer_wire_name(fromwire_peektype(msg)));
 
 	if (type == WIRE_GOSSIP_TIMESTAMP_FILTER) {
 		handle_gossip_timestamp_filter_in(peer, msg);

gossipd/gossmap_manage.c

@@ -862,6 +862,8 @@ const char *gossmap_manage_channel_update(const tal_t *ctx,
 	if (!gossmap_find_chan(gossmap, &scid)
 	    && source_peer
 	    && sigcheck_channel_update(tmpctx, source_peer, &signature, update) == NULL) {
+		status_debug("gossip update for unknown channel %s",
+			     type_to_string(tmpctx, struct short_channel_id, &scid));
 		tell_lightningd_peer_update(gm->daemon, source_peer,
 					    scid, fee_base_msat,
 					    fee_proportional_millionths,

tests/test_connection.py

@@ -992,7 +992,7 @@ def test_reconnect_remote_sends_no_sigs(node_factory):
     l2.daemon.wait_for_log('peer_out WIRE_ANNOUNCEMENT_SIGNATURES')
 
     l1msgs = [l.split()[4] for l in l1.daemon.logs[l1needle:] if 'WIRE_ANNOUNCEMENT_SIGNATURES' in l]
-    assert l1msgs == ['peer_out', 'peer_in']
+    assert l1msgs == ['Sending', 'peer_out', 'Gossip', 'peer_in']
 
     # l2 only sends one.
     assert len([l for l in l2.daemon.logs[l2needle:] if 'peer_out WIRE_ANNOUNCEMENT_SIGNATURES' in l]) == 1