From 559168dfff1d89a5c5c15949b4ff3de8e7dceca5 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 12 Feb 2024 09:52:19 +1030 Subject: [PATCH] patch bad-gossip-debug.patch --- connectd/connectd.c | 11 +++++++++-- connectd/multiplex.c | 22 ++++++++++++++++++---- gossipd/gossmap_manage.c | 2 ++ tests/test_connection.py | 2 +- 4 files changed, 30 insertions(+), 7 deletions(-) diff --git a/connectd/connectd.c b/connectd/connectd.c index 19ea0944aaa0..5af37325afd7 100644 --- a/connectd/connectd.c +++ b/connectd/connectd.c @@ -49,6 +49,7 @@ #include #include #include +#include #include #include @@ -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); } diff --git a/connectd/multiplex.c b/connectd/multiplex.c index 72b160353059..0c64413d89aa 100644 --- a/connectd/multiplex.c +++ b/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); diff --git a/gossipd/gossmap_manage.c b/gossipd/gossmap_manage.c index 4ec6235e293c..c51b73bd96f6 100644 --- a/gossipd/gossmap_manage.c +++ b/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, diff --git a/tests/test_connection.py b/tests/test_connection.py index eb4678e58cef..88c0a198bacc 100644 --- a/tests/test_connection.py +++ b/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