diff --git a/connectd/connectd.c b/connectd/connectd.c index fcc619112..9e0c23463 100644 --- a/connectd/connectd.c +++ b/connectd/connectd.c @@ -354,8 +354,7 @@ static struct io_plan *retry_peer_connected(struct io_conn *conn, struct io_plan *plan; /*~ As you can see, we've had issues with this code before :( */ - status_debug("peer %s: processing now old peer gone", - type_to_string(tmpctx, struct node_id, &pr->id)); + status_peer_debug(&pr->id, "processing now old peer gone"); /*~ Usually the pattern is to return this directly, but we have to free * our temporary structure. */ @@ -377,8 +376,7 @@ static struct io_plan *peer_reconnected(struct io_conn *conn, u8 *msg; struct peer_reconnected *pr; - status_debug("peer %s: reconnect", - type_to_string(tmpctx, struct node_id, id)); + status_peer_debug(id, "reconnect"); /* Tell master to kill it: will send peer_disconnect */ msg = towire_connect_reconnected(NULL, id); @@ -470,8 +468,7 @@ static struct io_plan *handshake_in_success(struct io_conn *conn, { struct node_id id; node_id_from_pubkey(&id, id_key); - status_debug("Connect IN from %s", - type_to_string(tmpctx, struct node_id, &id)); + status_peer_debug(&id, "Connect IN"); return peer_exchange_initmsg(conn, daemon, cs, &id, addr); } @@ -531,8 +528,7 @@ static struct io_plan *handshake_out_success(struct io_conn *conn, node_id_from_pubkey(&id, key); connect->connstate = "Exchanging init messages"; - status_debug("Connect OUT to %s", - type_to_string(tmpctx, struct node_id, &id)); + status_peer_debug(&id, "Connect OUT"); return peer_exchange_initmsg(conn, connect->daemon, cs, &id, addr); } @@ -549,8 +545,7 @@ struct io_plan *connection_out(struct io_conn *conn, struct connecting *connect) } /* FIXME: Timeout */ - status_debug("Connected out for %s", - type_to_string(tmpctx, struct node_id, &connect->id)); + status_peer_debug(&connect->id, "Connected out, starting crypto"); connect->connstate = "Cryptographic handshake"; return initiator_handshake(conn, &connect->daemon->mykey, &outkey, @@ -602,9 +597,7 @@ static void connect_failed(struct daemon *daemon, addrhint); daemon_conn_send(daemon->master, take(msg)); - status_debug("Failed connected out for %s: %s", - type_to_string(tmpctx, struct node_id, id), - err); + status_peer_debug(id, "Failed connected out: %s", err); } /*~ This is the destructor for the (unsuccessful) connection. We accumulate @@ -1279,7 +1272,7 @@ static void add_seed_addrs(struct wireaddr_internal **addrs, const char **hostnames = seednames(tmpctx, id); for (size_t i = 0; i < tal_count(hostnames); i++) { - status_debug("Resolving %s", hostnames[i]); + status_peer_debug(id, "Resolving %s", hostnames[i]); new_addrs = wireaddr_from_hostname(tmpctx, hostnames[i], DEFAULT_PORT, NULL, broken_reply, NULL); if (new_addrs) { @@ -1287,13 +1280,13 @@ static void add_seed_addrs(struct wireaddr_internal **addrs, struct wireaddr_internal a; a.itype = ADDR_INTERNAL_WIREADDR; a.u.wireaddr = new_addrs[j]; - status_debug("Resolved %s to %s", hostnames[i], - type_to_string(tmpctx, struct wireaddr, - &a.u.wireaddr)); + status_peer_debug(id, "Resolved %s to %s", hostnames[i], + type_to_string(tmpctx, struct wireaddr, + &a.u.wireaddr)); tal_arr_expand(addrs, a); } } else - status_debug("Could not resolve %s", hostnames[i]); + status_peer_debug(id, "Could not resolve %s", hostnames[i]); } } diff --git a/connectd/peer_exchange_initmsg.c b/connectd/peer_exchange_initmsg.c index bf0985e05..dfbd361f1 100644 --- a/connectd/peer_exchange_initmsg.c +++ b/connectd/peer_exchange_initmsg.c @@ -51,9 +51,9 @@ static struct io_plan *peer_init_received(struct io_conn *conn, return read_init(conn, peer); if (!fromwire_init(tmpctx, msg, &globalfeatures, &features)) { - status_debug("peer %s bad fromwire_init '%s', closing", - type_to_string(tmpctx, struct node_id, &peer->id), - tal_hex(tmpctx, msg)); + status_peer_debug(&peer->id, + "bad fromwire_init '%s', closing", + tal_hex(tmpctx, msg)); return io_close(conn); } diff --git a/contrib/pyln-testing/pyln/testing/fixtures.py b/contrib/pyln-testing/pyln/testing/fixtures.py index 970739716..dbda7d4de 100644 --- a/contrib/pyln-testing/pyln/testing/fixtures.py +++ b/contrib/pyln-testing/pyln/testing/fixtures.py @@ -239,7 +239,7 @@ def checkBadGossip(node): if node.allow_bad_gossip: return 0 # We can get bad gossip order from inside error msgs. - if node.daemon.is_in_log('Bad gossip order from (?!error)'): + if node.daemon.is_in_log('Bad gossip order:'): # This can happen if a node sees a node_announce after a channel # is deleted, however. if node.daemon.is_in_log('Deleting channel'): diff --git a/gossipd/gossip_generation.c b/gossipd/gossip_generation.c index f3ba34800..f1bed7df5 100644 --- a/gossipd/gossip_generation.c +++ b/gossipd/gossip_generation.c @@ -452,9 +452,8 @@ bool handle_local_channel_update(struct daemon *daemon, &lc->fee_base_msat, &lc->fee_proportional_millionths, &lc->htlc_maximum)) { - status_broken("peer %s bad local_channel_update %s", - type_to_string(tmpctx, struct node_id, src), - tal_hex(tmpctx, msg)); + status_peer_broken(src, "bad local_channel_update %s", + tal_hex(tmpctx, msg)); return false; } @@ -462,10 +461,9 @@ bool handle_local_channel_update(struct daemon *daemon, &scid); /* Can theoretically happen if channel just closed. */ if (!lc->local_chan) { - status_debug("peer %s local_channel_update for unknown %s", - type_to_string(tmpctx, struct node_id, src), - type_to_string(tmpctx, struct short_channel_id, - &scid)); + status_peer_debug(src, "local_channel_update for unknown %s", + type_to_string(tmpctx, struct short_channel_id, + &scid)); return true; } diff --git a/gossipd/gossip_store.c b/gossipd/gossip_store.c index eb6306b99..278c8436e 100644 --- a/gossipd/gossip_store.c +++ b/gossipd/gossip_store.c @@ -734,7 +734,8 @@ u32 gossip_store_load(struct routing_state *rstate, struct gossip_store *gs) stats[2]++; break; case WIRE_GOSSIPD_LOCAL_ADD_CHANNEL: - if (!handle_local_add_channel(rstate, msg, gs->len)) { + if (!handle_local_add_channel(rstate, NULL, + msg, gs->len)) { bad = "Bad local_add_channel"; goto badmsg; } diff --git a/gossipd/gossipd.c b/gossipd/gossipd.c index ed936807f..7496d6f4e 100644 --- a/gossipd/gossipd.c +++ b/gossipd/gossipd.c @@ -380,10 +380,9 @@ static bool handle_get_local_channel_update(struct peer *peer, const u8 *msg) update = gossip_store_get(tmpctx, rstate->gs, chan->half[local_chan->direction].bcast.index); out: - status_debug("peer %s schanid %s: %s update", - type_to_string(tmpctx, struct node_id, &peer->id), - type_to_string(tmpctx, struct short_channel_id, &scid), - update ? "got" : "no"); + status_peer_debug(&peer->id, "schanid %s: %s update", + type_to_string(tmpctx, struct short_channel_id, &scid), + update ? "got" : "no"); msg = towire_gossipd_get_update_reply(NULL, update); daemon_conn_send(peer->dc, take(msg)); @@ -501,7 +500,8 @@ static struct io_plan *peer_msg_in(struct io_conn *conn, ok = handle_get_local_channel_update(peer, msg); goto handled_cmd; case WIRE_GOSSIPD_LOCAL_ADD_CHANNEL: - ok = handle_local_add_channel(peer->daemon->rstate, msg, 0); + ok = handle_local_add_channel(peer->daemon->rstate, peer, + msg, 0); goto handled_cmd; case WIRE_GOSSIPD_LOCAL_CHANNEL_UPDATE: ok = handle_local_channel_update(peer->daemon, &peer->id, msg); @@ -517,10 +517,9 @@ static struct io_plan *peer_msg_in(struct io_conn *conn, } /* Anything else should not have been sent to us: close on it */ - status_broken("peer %s: unexpected cmd of type %i %s", - type_to_string(tmpctx, struct node_id, &peer->id), - fromwire_peektype(msg), - gossip_peerd_wire_type_name(fromwire_peektype(msg))); + status_peer_broken(&peer->id, "unexpected cmd of type %i %s", + fromwire_peektype(msg), + gossip_peerd_wire_type_name(fromwire_peektype(msg))); return io_close(conn); /* Commands should always be OK. */ @@ -1149,8 +1148,8 @@ static struct io_plan *ping_req(struct io_conn *conn, struct daemon *daemon, status_failed(STATUS_FAIL_MASTER_IO, "Oversize ping"); queue_peer_msg(peer, take(ping)); - status_debug("sending ping expecting %sresponse", - num_pong_bytes >= 65532 ? "no " : ""); + status_peer_debug(&peer->id, "sending ping expecting %sresponse", + num_pong_bytes >= 65532 ? "no " : ""); /* BOLT #1: * diff --git a/gossipd/queries.c b/gossipd/queries.c index 00f116802..84cbec030 100644 --- a/gossipd/queries.c +++ b/gossipd/queries.c @@ -229,9 +229,8 @@ bool query_short_channel_ids(struct daemon *daemon, peer->scid_query_outstanding = true; peer->scid_query_cb = cb; - status_debug("%s: sending query for %zu scids", - type_to_string(tmpctx, struct node_id, &peer->id), - tal_count(scids)); + status_peer_debug(&peer->id, "sending query for %zu scids", + tal_count(scids)); return true; } @@ -280,9 +279,9 @@ const u8 *handle_query_short_channel_ids(struct peer *peer, const u8 *msg) * - MUST set `complete` to 0. */ if (!bitcoin_blkid_eq(&peer->daemon->chain_hash, &chain)) { - status_debug("%s sent query_short_channel_ids chainhash %s", - type_to_string(tmpctx, struct node_id, &peer->id), - type_to_string(tmpctx, struct bitcoin_blkid, &chain)); + status_peer_debug(&peer->id, + "sent query_short_channel_ids chainhash %s", + type_to_string(tmpctx, struct bitcoin_blkid, &chain)); return towire_reply_short_channel_ids_end(peer, &chain, 0); } @@ -597,10 +596,10 @@ const u8 *handle_query_channel_range(struct peer *peer, const u8 *msg) * - MUST set `complete` to 0. */ if (!bitcoin_blkid_eq(&peer->daemon->chain_hash, &chain_hash)) { - status_debug("%s sent query_channel_range chainhash %s", - type_to_string(tmpctx, struct node_id, &peer->id), - type_to_string(tmpctx, struct bitcoin_blkid, - &chain_hash)); + status_peer_debug(&peer->id, + "query_channel_range with chainhash %s", + type_to_string(tmpctx, struct bitcoin_blkid, + &chain_hash)); u8 *end = towire_reply_channel_range(NULL, &chain_hash, first_blocknum, number_of_blocks, false, NULL, NULL); queue_peer_msg(peer, take(end)); @@ -687,12 +686,12 @@ const u8 *handle_reply_channel_range(struct peer *peer, const u8 *msg) tal_hex(tmpctx, encoded)); } - status_debug("peer %s reply_channel_range %u+%u (of %u+%u) %zu scids", - type_to_string(tmpctx, struct node_id, &peer->id), - first_blocknum, number_of_blocks, - peer->range_first_blocknum, - peer->range_end_blocknum - peer->range_first_blocknum, - tal_count(scids)); + status_peer_debug(&peer->id, + "reply_channel_range %u+%u (of %u+%u) %zu scids", + first_blocknum, number_of_blocks, + peer->range_first_blocknum, + peer->range_end_blocknum - peer->range_first_blocknum, + tal_count(scids)); /* BOLT #7: * @@ -1030,8 +1029,9 @@ bool query_channel_range(struct daemon *daemon, tlvs->query_option->query_option_flags = qflags; } else tlvs = NULL; - status_debug("sending query_channel_range for blocks %u+%u", - first_blocknum, number_of_blocks); + status_peer_debug(&peer->id, + "sending query_channel_range for blocks %u+%u", + first_blocknum, number_of_blocks); msg = towire_query_channel_range(NULL, &daemon->chain_hash, first_blocknum, number_of_blocks, diff --git a/gossipd/routing.c b/gossipd/routing.c index 756526877..2dfb6a397 100644 --- a/gossipd/routing.c +++ b/gossipd/routing.c @@ -533,10 +533,10 @@ static void bad_gossip_order(const u8 *msg, const struct peer *peer, const char *details) { - status_debug("Bad gossip order from %s: %s before announcement %s", - peer ? type_to_string(tmpctx, struct node_id, &peer->id) - : "unknown", wire_type_name(fromwire_peektype(msg)), - details); + status_peer_debug(peer ? &peer->id : NULL, + "Bad gossip order: %s before announcement %s", + wire_type_name(fromwire_peektype(msg)), + details); } static void destroy_local_chan(struct local_chan *local_chan, @@ -1714,11 +1714,12 @@ u8 *handle_channel_announcement(struct routing_state *rstate, * anyway. */ if (current_blockheight != 0 && short_channel_id_blocknum(&pending->short_channel_id) > current_blockheight) { - status_debug("Ignoring future channel_announcment for %s" - " (current block %u)", - type_to_string(tmpctx, struct short_channel_id, - &pending->short_channel_id), - current_blockheight); + status_peer_debug(peer ? &peer->id : NULL, + "Ignoring future channel_announcment for %s" + " (current block %u)", + type_to_string(tmpctx, struct short_channel_id, + &pending->short_channel_id), + current_blockheight); goto ignored; } @@ -1771,7 +1772,7 @@ u8 *handle_channel_announcement(struct routing_state *rstate, */ if (!bitcoin_blkid_eq(&chain_hash, &rstate->chainparams->genesis_blockhash)) { - status_debug( + status_peer_debug(peer ? &peer->id : NULL, "Received channel_announcement %s for unknown chain %s", type_to_string(pending, struct short_channel_id, &pending->short_channel_id), @@ -1808,16 +1809,18 @@ u8 *handle_channel_announcement(struct routing_state *rstate, > 100000) { static bool warned = false; if (!warned) { - status_unusual("Flooded by channel_announcements:" - " ignoring some"); + status_peer_unusual(peer ? &peer->id : NULL, + "Flooded by channel_announcements:" + " ignoring some"); warned = true; } goto ignored; } - status_debug("Received channel_announcement for channel %s", - type_to_string(tmpctx, struct short_channel_id, - &pending->short_channel_id)); + status_peer_debug(peer ? &peer->id : NULL, + "Received channel_announcement for channel %s", + type_to_string(tmpctx, struct short_channel_id, + &pending->short_channel_id)); /* Add both endpoints to the pending_node_map so we can stash * node_announcements while we wait for the txout check */ @@ -1858,12 +1861,11 @@ static void process_pending_channel_update(struct daemon *daemon, err = handle_channel_update(rstate, cupdate, peer, NULL); if (err) { /* FIXME: We could send this error back to peer if != NULL */ - status_debug("Pending channel_update for %s from %s: %s", - type_to_string(tmpctx, struct short_channel_id, scid), - peer - ? type_to_string(tmpctx, struct node_id, &peer->id) - : "unknown", - sanitize_error(tmpctx, err, NULL)); + status_peer_debug(peer ? &peer->id : NULL, + "Pending channel_update for %s: %s", + type_to_string(tmpctx, struct short_channel_id, + scid), + sanitize_error(tmpctx, err, NULL)); tal_free(err); } } @@ -1876,11 +1878,14 @@ bool handle_pending_cannouncement(struct daemon *daemon, { const u8 *s; struct pending_cannouncement *pending; + const struct node_id *src; pending = find_pending_cannouncement(rstate, scid); if (!pending) return false; + src = pending->peer_softref ? &pending->peer_softref->id : NULL; + /* BOLT #7: * * The receiving node: @@ -1889,9 +1894,11 @@ bool handle_pending_cannouncement(struct daemon *daemon, * - MUST ignore the message. */ if (tal_count(outscript) == 0) { - status_debug("channel_announcement: no unspent txout %s", - type_to_string(pending, struct short_channel_id, - scid)); + status_peer_debug(src, + "channel_announcement: no unspent txout %s", + type_to_string(pending, + struct short_channel_id, + scid)); tal_free(pending); add_to_txout_failures(rstate, scid); return false; @@ -1912,10 +1919,13 @@ bool handle_pending_cannouncement(struct daemon *daemon, &pending->bitcoin_key_2)); if (!scripteq(s, outscript)) { - status_debug("channel_announcement: txout %s expectes %s, got %s", - type_to_string(pending, struct short_channel_id, - scid), - tal_hex(tmpctx, s), tal_hex(tmpctx, outscript)); + status_peer_debug(src, + "channel_announcement: txout %s expected %s, got %s", + type_to_string( + pending, struct short_channel_id, + scid), + tal_hex(tmpctx, s), + tal_hex(tmpctx, outscript)); tal_free(pending); return false; } @@ -1927,8 +1937,9 @@ bool handle_pending_cannouncement(struct daemon *daemon, /* Can fail if channel_announcement too old */ if (!routing_add_channel_announcement(rstate, pending->announce, sat, 0, pending->peer_softref)) - status_unusual("Could not add channel_announcement %s: too old?", - tal_hex(tmpctx, pending->announce)); + status_peer_unusual(src, + "Could not add channel_announcement %s: too old?", + tal_hex(tmpctx, pending->announce)); else { /* Did we have an update waiting? If so, apply now. */ process_pending_channel_update(daemon, rstate, scid, pending->updates[0], @@ -1952,7 +1963,8 @@ static void update_pending(struct pending_cannouncement *pending, if (pending->update_timestamps[direction] < timestamp) { if (pending->updates[direction]) { - status_debug("Replacing existing update"); + status_peer_debug(peer ? &peer->id : NULL, + "Replacing existing update"); tal_free(pending->updates[direction]); } pending->updates[direction] = tal_dup_arr(pending, u8, update, tal_count(update), 0); @@ -2056,21 +2068,23 @@ bool routing_add_channel_update(struct routing_state *rstate, } else { /* If not indicated, set htlc_max_msat to channel capacity */ if (!amount_sat_to_msat(&htlc_maximum, sat)) { - status_broken("Channel capacity %s overflows!", - type_to_string(tmpctx, struct amount_sat, - &sat)); + status_peer_broken(peer ? &peer->id : NULL, + "Channel capacity %s overflows!", + type_to_string(tmpctx, struct amount_sat, + &sat)); return false; } } /* Check timestamp is sane (unless from store). */ if (!index && !timestamp_reasonable(rstate, timestamp)) { - status_debug("Ignoring update timestamp %u for %s/%u", - timestamp, - type_to_string(tmpctx, - struct short_channel_id, - &short_channel_id), - direction); + status_peer_debug(peer ? &peer->id : NULL, + "Ignoring update timestamp %u for %s/%u", + timestamp, + type_to_string(tmpctx, + struct short_channel_id, + &short_channel_id), + direction); return false; } @@ -2101,12 +2115,14 @@ bool routing_add_channel_update(struct routing_state *rstate, /* Allow redundant updates once every 7 days */ if (timestamp < hc->bcast.timestamp + GOSSIP_PRUNE_INTERVAL(rstate->dev_fast_gossip_prune) / 2 && !cupdate_different(rstate->gs, hc, update)) { - status_debug("Ignoring redundant update for %s/%u" - " (last %u, now %u)", - type_to_string(tmpctx, - struct short_channel_id, - &short_channel_id), - direction, hc->bcast.timestamp, timestamp); + status_peer_debug(peer ? &peer->id : NULL, + "Ignoring redundant update for %s/%u" + " (last %u, now %u)", + type_to_string(tmpctx, + struct short_channel_id, + &short_channel_id), + direction, + hc->bcast.timestamp, timestamp); /* Ignoring != failing */ return true; } @@ -2114,12 +2130,14 @@ bool routing_add_channel_update(struct routing_state *rstate, /* Make sure it's not spamming us. */ if (!ratelimit(rstate, &hc->tokens, hc->bcast.timestamp, timestamp)) { - status_debug("Ignoring spammy update for %s/%u" - " (last %u, now %u)", - type_to_string(tmpctx, - struct short_channel_id, - &short_channel_id), - direction, hc->bcast.timestamp, timestamp); + status_peer_debug(peer ? &peer->id : NULL, + "Ignoring spammy update for %s/%u" + " (last %u, now %u)", + type_to_string(tmpctx, + struct short_channel_id, + &short_channel_id), + direction, + hc->bcast.timestamp, timestamp); /* Ignoring != failing */ return true; } @@ -2285,9 +2303,10 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update TAKES, */ if (!bitcoin_blkid_eq(&chain_hash, &rstate->chainparams->genesis_blockhash)) { - status_debug("Received channel_update for unknown chain %s", - type_to_string(tmpctx, struct bitcoin_blkid, - &chain_hash)); + status_peer_debug(peer ? &peer->id : NULL, + "Received channel_update for unknown chain %s", + type_to_string(tmpctx, struct bitcoin_blkid, + &chain_hash)); return NULL; } @@ -2300,11 +2319,12 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update TAKES, /* If we have an unvalidated channel, just queue on that */ pending = find_pending_cannouncement(rstate, &short_channel_id); if (pending) { - status_debug("Updated pending announce with update %s/%u", - type_to_string(tmpctx, - struct short_channel_id, - &short_channel_id), - direction); + status_peer_debug(peer ? &peer->id : NULL, + "Updated pending announce with update %s/%u", + type_to_string(tmpctx, + struct short_channel_id, + &short_channel_id), + direction); update_pending(pending, timestamp, serialized, direction, peer); return NULL; } @@ -2337,13 +2357,12 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update TAKES, return err; } - status_debug("Received channel_update for channel %s/%d now %s (from %s)", - type_to_string(tmpctx, struct short_channel_id, - &short_channel_id), - channel_flags & 0x01, - channel_flags & ROUTING_FLAGS_DISABLED ? "DISABLED" : "ACTIVE", - peer ? type_to_string(tmpctx, struct node_id, &peer->id) - : "unknown"); + status_peer_debug(peer ? &peer->id : NULL, + "Received channel_update for channel %s/%d now %s", + type_to_string(tmpctx, struct short_channel_id, + &short_channel_id), + channel_flags & 0x01, + channel_flags & ROUTING_FLAGS_DISABLED ? "DISABLED" : "ACTIVE"); routing_add_channel_update(rstate, take(serialized), 0, peer); return NULL; @@ -2411,8 +2430,10 @@ bool routing_add_node_announcement(struct routing_state *rstate, /* Only log this if *not* loading from store. */ if (!index) - status_debug("Received node_announcement for node %s", - type_to_string(tmpctx, struct node_id, &node_id)); + status_peer_debug(peer ? &peer->id : NULL, + "Received node_announcement for node %s", + type_to_string(tmpctx, struct node_id, + &node_id)); node = get_node(rstate, &node_id); @@ -2470,12 +2491,13 @@ bool routing_add_node_announcement(struct routing_state *rstate, /* Allow redundant updates once every 7 days */ if (timestamp < node->bcast.timestamp + GOSSIP_PRUNE_INTERVAL(rstate->dev_fast_gossip_prune) / 2 && !nannounce_different(rstate->gs, node, msg)) { - status_debug("Ignoring redundant nannounce for %s" - " (last %u, now %u)", - type_to_string(tmpctx, - struct node_id, - &node_id), - node->bcast.timestamp, timestamp); + status_peer_debug(peer ? &peer->id : NULL, + "Ignoring redundant nannounce for %s" + " (last %u, now %u)", + type_to_string(tmpctx, + struct node_id, + &node_id), + node->bcast.timestamp, timestamp); /* Ignoring != failing */ return true; } @@ -2483,12 +2505,13 @@ bool routing_add_node_announcement(struct routing_state *rstate, /* Make sure it's not spamming us. */ if (!ratelimit(rstate, &node->tokens, node->bcast.timestamp, timestamp)) { - status_debug("Ignoring spammy nannounce for %s" - " (last %u, now %u)", - type_to_string(tmpctx, - struct node_id, - &node_id), - node->bcast.timestamp, timestamp); + status_peer_debug(peer ? &peer->id : NULL, + "Ignoring spammy nannounce for %s" + " (last %u, now %u)", + type_to_string(tmpctx, + struct node_id, + &node_id), + node->bcast.timestamp, timestamp); /* Ignoring != failing */ return true; } @@ -2868,6 +2891,7 @@ void route_prune(struct routing_state *rstate) } bool handle_local_add_channel(struct routing_state *rstate, + const struct peer *peer, const u8 *msg, u64 index) { struct short_channel_id scid; @@ -2877,19 +2901,22 @@ bool handle_local_add_channel(struct routing_state *rstate, if (!fromwire_gossipd_local_add_channel(msg, &scid, &remote_node_id, &sat)) { - status_broken("Unable to parse local_add_channel message: %s", - tal_hex(msg, msg)); + status_peer_broken(peer ? &peer->id : NULL, + "Unable to parse local_add_channel message: %s", + tal_hex(msg, msg)); return false; } /* Can happen on channeld restart. */ if (get_channel(rstate, &scid)) { - status_debug("Attempted to local_add_channel a known channel"); + status_peer_debug(peer ? &peer->id : NULL, + "Attempted to local_add_channel a known channel"); return true; } - status_debug("local_add_channel %s", - type_to_string(tmpctx, struct short_channel_id, &scid)); + status_peer_debug(peer ? &peer->id : NULL, + "local_add_channel %s", + type_to_string(tmpctx, struct short_channel_id, &scid)); /* Create new (unannounced) channel */ chan = new_chan(rstate, &scid, &rstate->local_id, &remote_node_id, sat); diff --git a/gossipd/routing.h b/gossipd/routing.h index 7c43bcea8..ea159b7a7 100644 --- a/gossipd/routing.h +++ b/gossipd/routing.h @@ -482,7 +482,9 @@ bool routing_add_node_announcement(struct routing_state *rstate, * is the case for private channels or channels that have not yet reached * `announce_depth`. */ -bool handle_local_add_channel(struct routing_state *rstate, const u8 *msg, +bool handle_local_add_channel(struct routing_state *rstate, + const struct peer *peer, + const u8 *msg, u64 index); /** diff --git a/gossipd/seeker.c b/gossipd/seeker.c index 5856d58ae..24e5cf5fe 100644 --- a/gossipd/seeker.c +++ b/gossipd/seeker.c @@ -126,11 +126,9 @@ static void set_state_(struct seeker *seeker, enum seeker_state state, { va_list ap; va_start(ap, fmt); - status_debug("seeker: state = %s %s%s %s", - statename, peer ? "from " : "", - peer ? type_to_string(tmpctx, struct node_id, &peer->id) - : "", - tal_vfmt(tmpctx, fmt, ap)); + status_peer_debug(peer ? &peer->id : NULL, + "seeker: state = %s %s", + statename, tal_vfmt(tmpctx, fmt, ap)); va_end(ap); seeker->state = state; selected_peer(seeker, peer); @@ -202,8 +200,7 @@ static void disable_gossip_stream(struct seeker *seeker, struct peer *peer) { u8 *msg; - status_debug("seeker: disabling gossip from %s", - type_to_string(tmpctx, struct node_id, &peer->id)); + status_peer_debug(&peer->id, "seeker: disabling gossip"); /* This is allowed even if they don't understand it (odd) */ msg = towire_gossip_timestamp_filter(NULL, @@ -230,8 +227,7 @@ static void enable_gossip_stream(struct seeker *seeker, struct peer *peer) else start = 0; - status_debug("seeker: starting gossip from %s", - type_to_string(tmpctx, struct node_id, &peer->id)); + status_peer_debug(&peer->id, "seeker: starting gossip"); /* This is allowed even if they don't understand it (odd) */ msg = towire_gossip_timestamp_filter(NULL, @@ -284,8 +280,7 @@ static struct short_channel_id *unknown_scids_remove(const tal_t *ctx, /* We have selected this peer to stream us startup gossip */ static void peer_gossip_startup(struct seeker *seeker, struct peer *peer) { - status_debug("seeker: startup peer is %s", - type_to_string(tmpctx, struct node_id, &peer->id)); + status_peer_debug(&peer->id, "seeker: chosen as startup peer"); selected_peer(seeker, peer); normal_gossip_start(seeker, peer); } @@ -520,8 +515,7 @@ static void nodeannounce_query_done(struct peer *peer, bool complete) /* We might have given up on them, then they replied. */ if (seeker->random_peer_softref != peer) { - status_debug("seeker: belated reply from %s: ignoring", - type_to_string(tmpctx, struct node_id, &peer->id)); + status_peer_debug(&peer->id, "seeker: belated reply: ignoring"); return; } @@ -542,8 +536,9 @@ static void nodeannounce_query_done(struct peer *peer, bool complete) new_nannounce++; } - status_debug("seeker: found %zu new node_announcements in %zu scids", - new_nannounce, num_scids); + status_peer_debug(&peer->id, + "seeker: found %zu new node_announcements in %zu scids", + new_nannounce, num_scids); seeker->nannounce_scids = tal_free(seeker->nannounce_scids); seeker->nannounce_query_flags = tal_free(seeker->nannounce_query_flags); @@ -780,7 +775,7 @@ static void check_firstpeer(struct seeker *seeker) return; /* Other peers can gossip now. */ - status_debug("seeker: startup peer finished"); + status_peer_debug(&peer->id, "seeker: startup peer finished"); clear_softref(seeker, &seeker->random_peer_softref); list_for_each(&seeker->daemon->peers, p, list) { if (p == peer) @@ -812,9 +807,9 @@ static void check_probe(struct seeker *seeker, if (peer_made_progress(seeker)) return; - status_debug("Peer %s has only moved gossip %zu->%zu for probe, giving up on it", - type_to_string(tmpctx, struct node_id, &peer->id), - seeker->prev_gossip_count, peer->gossip_counter); + status_peer_debug(&peer->id, + "has only moved gossip %zu->%zu for probe, giving up on it", + seeker->prev_gossip_count, peer->gossip_counter); clear_softref(seeker, &seeker->random_peer_softref); restart(seeker); } @@ -845,15 +840,14 @@ static void maybe_rotate_gossipers(struct seeker *seeker) /* If we have a slot free, or ~ 1 per hour */ for (i = 0; i < ARRAY_SIZE(seeker->gossiper_softref); i++) { if (!seeker->gossiper_softref[i]) { - status_debug("seeker: filling slot %zu with %s", - i, type_to_string(tmpctx, struct node_id, - &peer->id)); + status_peer_debug(&peer->id, "seeker: filling slot %zu", + i); goto set_gossiper; } if (pseudorand(ARRAY_SIZE(seeker->gossiper_softref) * 60) == 0) { - status_debug("seeker: replacing slot %zu with %s", - i, type_to_string(tmpctx, struct node_id, - &peer->id)); + status_peer_debug(&peer->id, + "seeker: replacing slot %zu", + i); goto clear_and_set_gossiper; } } diff --git a/gossipd/test/run-find_route-specific.c b/gossipd/test/run-find_route-specific.c index 2adc4214f..cc5e8c99e 100644 --- a/gossipd/test/run-find_route-specific.c +++ b/gossipd/test/run-find_route-specific.c @@ -9,7 +9,7 @@ #include #define status_fmt(level, node_id, fmt, ...) \ - do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0) + do { (void)node_id; printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0) #include "../routing.c" #include "../gossip_store.c" diff --git a/tests/test_connection.py b/tests/test_connection.py index 6c4833830..a215be0c8 100644 --- a/tests/test_connection.py +++ b/tests/test_connection.py @@ -235,7 +235,7 @@ def test_disconnect(node_factory): # Should have 3 connect fails. for d in disconnects: - l1.daemon.wait_for_log('Failed connected out for {}' + l1.daemon.wait_for_log('{}-.*Failed connected out' .format(l2.info['id'])) # Should still only have one peer!