mirrors/core-lightning
1
0
Fork 0
mirror of https://github.com/ElementsProject/lightning.git synced 2025-01-18 05:12:45 +01:00
Code Issues Projects Releases Wiki Activity

connectd, gossipd: use per-peer logging.

Browse Source 
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This commit is contained in:
Rusty Russell 2019-11-18 10:56:17 +10:30
parent 00cb5adfe6
commit eed654f684
12 changed files with 187 additions and 173 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

29
connectd/connectd.c
View File

@ -354,8 +354,7 @@ static struct io_plan *retry_peer_connected(struct io_conn *conn,
struct io_plan *plan; struct io_plan *plan;
/*~ As you can see, we've had issues with this code before :( */ /*~ As you can see, we've had issues with this code before :( */
status_debug("peer %s: processing now old peer gone", status_peer_debug(&pr->id, "processing now old peer gone");
type_to_string(tmpctx, struct node_id, &pr->id));
/*~ Usually the pattern is to return this directly, but we have to free /*~ Usually the pattern is to return this directly, but we have to free
* our temporary structure. */ * our temporary structure. */
@ -377,8 +376,7 @@ static struct io_plan *peer_reconnected(struct io_conn *conn,
u8 *msg; u8 *msg;
struct peer_reconnected *pr; struct peer_reconnected *pr;
status_debug("peer %s: reconnect", status_peer_debug(id, "reconnect");
type_to_string(tmpctx, struct node_id, id));
/* Tell master to kill it: will send peer_disconnect */ /* Tell master to kill it: will send peer_disconnect */
msg = towire_connect_reconnected(NULL, id); 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; struct node_id id;
node_id_from_pubkey(&id, id_key); node_id_from_pubkey(&id, id_key);
status_debug("Connect IN from %s", status_peer_debug(&id, "Connect IN");
type_to_string(tmpctx, struct node_id, &id));
return peer_exchange_initmsg(conn, daemon, cs, &id, addr); 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); node_id_from_pubkey(&id, key);
connect->connstate = "Exchanging init messages"; connect->connstate = "Exchanging init messages";
status_debug("Connect OUT to %s", status_peer_debug(&id, "Connect OUT");
type_to_string(tmpctx, struct node_id, &id));
return peer_exchange_initmsg(conn, connect->daemon, cs, &id, addr); 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 */ /* FIXME: Timeout */
status_debug("Connected out for %s", status_peer_debug(&connect->id, "Connected out, starting crypto");
type_to_string(tmpctx, struct node_id, &connect->id));
connect->connstate = "Cryptographic handshake"; connect->connstate = "Cryptographic handshake";
return initiator_handshake(conn, &connect->daemon->mykey, &outkey, return initiator_handshake(conn, &connect->daemon->mykey, &outkey,
@ -602,9 +597,7 @@ static void connect_failed(struct daemon *daemon,
addrhint); addrhint);
daemon_conn_send(daemon->master, take(msg)); daemon_conn_send(daemon->master, take(msg));
status_debug("Failed connected out for %s: %s", status_peer_debug(id, "Failed connected out: %s", err);
type_to_string(tmpctx, struct node_id, id),
err);
} }
/*~ This is the destructor for the (unsuccessful) connection. We accumulate /*~ 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); const char **hostnames = seednames(tmpctx, id);
for (size_t i = 0; i < tal_count(hostnames); i++) { 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, new_addrs = wireaddr_from_hostname(tmpctx, hostnames[i], DEFAULT_PORT,
NULL, broken_reply, NULL); NULL, broken_reply, NULL);
if (new_addrs) { if (new_addrs) {
@ -1287,13 +1280,13 @@ static void add_seed_addrs(struct wireaddr_internal **addrs,
struct wireaddr_internal a; struct wireaddr_internal a;
a.itype = ADDR_INTERNAL_WIREADDR; a.itype = ADDR_INTERNAL_WIREADDR;
a.u.wireaddr = new_addrs[j]; a.u.wireaddr = new_addrs[j];
status_debug("Resolved %s to %s", hostnames[i], status_peer_debug(id, "Resolved %s to %s", hostnames[i],
type_to_string(tmpctx, struct wireaddr, type_to_string(tmpctx, struct wireaddr,
&a.u.wireaddr)); &a.u.wireaddr));
tal_arr_expand(addrs, a); tal_arr_expand(addrs, a);
} }
} else } else
status_debug("Could not resolve %s", hostnames[i]); status_peer_debug(id, "Could not resolve %s", hostnames[i]);
} }
} }

6
connectd/peer_exchange_initmsg.c
View File

@ -51,9 +51,9 @@ static struct io_plan *peer_init_received(struct io_conn *conn,
return read_init(conn, peer); return read_init(conn, peer);
if (!fromwire_init(tmpctx, msg, &globalfeatures, &features)) { if (!fromwire_init(tmpctx, msg, &globalfeatures, &features)) {
status_debug("peer %s bad fromwire_init '%s', closing", status_peer_debug(&peer->id,
type_to_string(tmpctx, struct node_id, &peer->id), "bad fromwire_init '%s', closing",
tal_hex(tmpctx, msg)); tal_hex(tmpctx, msg));
return io_close(conn); return io_close(conn);
} }

2
contrib/pyln-testing/pyln/testing/fixtures.py
View File

@ -239,7 +239,7 @@ def checkBadGossip(node):
if node.allow_bad_gossip: if node.allow_bad_gossip:
return 0 return 0
# We can get bad gossip order from inside error msgs. # 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 # This can happen if a node sees a node_announce after a channel
# is deleted, however. # is deleted, however.
if node.daemon.is_in_log('Deleting channel'): if node.daemon.is_in_log('Deleting channel'):

12
gossipd/gossip_generation.c
View File

@ -452,9 +452,8 @@ bool handle_local_channel_update(struct daemon *daemon,
&lc->fee_base_msat, &lc->fee_base_msat,
&lc->fee_proportional_millionths, &lc->fee_proportional_millionths,
&lc->htlc_maximum)) { &lc->htlc_maximum)) {
status_broken("peer %s bad local_channel_update %s", status_peer_broken(src, "bad local_channel_update %s",
type_to_string(tmpctx, struct node_id, src), tal_hex(tmpctx, msg));
tal_hex(tmpctx, msg));
return false; return false;
} }
@ -462,10 +461,9 @@ bool handle_local_channel_update(struct daemon *daemon,
&scid); &scid);
/* Can theoretically happen if channel just closed. */ /* Can theoretically happen if channel just closed. */
if (!lc->local_chan) { if (!lc->local_chan) {
status_debug("peer %s local_channel_update for unknown %s", status_peer_debug(src, "local_channel_update for unknown %s",
type_to_string(tmpctx, struct node_id, src), type_to_string(tmpctx, struct short_channel_id,
type_to_string(tmpctx, struct short_channel_id, &scid));
&scid));
return true; return true;
} }

3
gossipd/gossip_store.c
View File

@ -734,7 +734,8 @@ u32 gossip_store_load(struct routing_state *rstate, struct gossip_store *gs)
stats[2]++; stats[2]++;
break; break;
case WIRE_GOSSIPD_LOCAL_ADD_CHANNEL: 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"; bad = "Bad local_add_channel";
goto badmsg; goto badmsg;
} }

21
gossipd/gossipd.c
View File

@ -380,10 +380,9 @@ static bool handle_get_local_channel_update(struct peer *peer, const u8 *msg)
update = gossip_store_get(tmpctx, rstate->gs, update = gossip_store_get(tmpctx, rstate->gs,
chan->half[local_chan->direction].bcast.index); chan->half[local_chan->direction].bcast.index);
out: out:
status_debug("peer %s schanid %s: %s update", status_peer_debug(&peer->id, "schanid %s: %s update",
type_to_string(tmpctx, struct node_id, &peer->id), type_to_string(tmpctx, struct short_channel_id, &scid),
type_to_string(tmpctx, struct short_channel_id, &scid), update ? "got" : "no");
update ? "got" : "no");
msg = towire_gossipd_get_update_reply(NULL, update); msg = towire_gossipd_get_update_reply(NULL, update);
daemon_conn_send(peer->dc, take(msg)); 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); ok = handle_get_local_channel_update(peer, msg);
goto handled_cmd; goto handled_cmd;
case WIRE_GOSSIPD_LOCAL_ADD_CHANNEL: 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; goto handled_cmd;
case WIRE_GOSSIPD_LOCAL_CHANNEL_UPDATE: case WIRE_GOSSIPD_LOCAL_CHANNEL_UPDATE:
ok = handle_local_channel_update(peer->daemon, &peer->id, msg); 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 */ /* Anything else should not have been sent to us: close on it */
status_broken("peer %s: unexpected cmd of type %i %s", status_peer_broken(&peer->id, "unexpected cmd of type %i %s",
type_to_string(tmpctx, struct node_id, &peer->id), fromwire_peektype(msg),
fromwire_peektype(msg), gossip_peerd_wire_type_name(fromwire_peektype(msg)));
gossip_peerd_wire_type_name(fromwire_peektype(msg)));
return io_close(conn); return io_close(conn);
/* Commands should always be OK. */ /* 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"); status_failed(STATUS_FAIL_MASTER_IO, "Oversize ping");
queue_peer_msg(peer, take(ping)); queue_peer_msg(peer, take(ping));
status_debug("sending ping expecting %sresponse", status_peer_debug(&peer->id, "sending ping expecting %sresponse",
num_pong_bytes >= 65532 ? "no " : ""); num_pong_bytes >= 65532 ? "no " : "");
/* BOLT #1: /* BOLT #1:
* *

36
gossipd/queries.c
View File

@ -229,9 +229,8 @@ bool query_short_channel_ids(struct daemon *daemon,
peer->scid_query_outstanding = true; peer->scid_query_outstanding = true;
peer->scid_query_cb = cb; peer->scid_query_cb = cb;
status_debug("%s: sending query for %zu scids", status_peer_debug(&peer->id, "sending query for %zu scids",
type_to_string(tmpctx, struct node_id, &peer->id), tal_count(scids));
tal_count(scids));
return true; return true;
} }
@ -280,9 +279,9 @@ const u8 *handle_query_short_channel_ids(struct peer *peer, const u8 *msg)
* - MUST set `complete` to 0. * - MUST set `complete` to 0.
*/ */
if (!bitcoin_blkid_eq(&peer->daemon->chain_hash, &chain)) { if (!bitcoin_blkid_eq(&peer->daemon->chain_hash, &chain)) {
status_debug("%s sent query_short_channel_ids chainhash %s", status_peer_debug(&peer->id,
type_to_string(tmpctx, struct node_id, &peer->id), "sent query_short_channel_ids chainhash %s",
type_to_string(tmpctx, struct bitcoin_blkid, &chain)); type_to_string(tmpctx, struct bitcoin_blkid, &chain));
return towire_reply_short_channel_ids_end(peer, &chain, 0); 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. * - MUST set `complete` to 0.
*/ */
if (!bitcoin_blkid_eq(&peer->daemon->chain_hash, &chain_hash)) { if (!bitcoin_blkid_eq(&peer->daemon->chain_hash, &chain_hash)) {
status_debug("%s sent query_channel_range chainhash %s", status_peer_debug(&peer->id,
type_to_string(tmpctx, struct node_id, &peer->id), "query_channel_range with chainhash %s",
type_to_string(tmpctx, struct bitcoin_blkid, type_to_string(tmpctx, struct bitcoin_blkid,
&chain_hash)); &chain_hash));
u8 *end = towire_reply_channel_range(NULL, &chain_hash, first_blocknum, u8 *end = towire_reply_channel_range(NULL, &chain_hash, first_blocknum,
number_of_blocks, false, NULL, NULL); number_of_blocks, false, NULL, NULL);
queue_peer_msg(peer, take(end)); 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)); tal_hex(tmpctx, encoded));
} }
status_debug("peer %s reply_channel_range %u+%u (of %u+%u) %zu scids", status_peer_debug(&peer->id,
type_to_string(tmpctx, struct node_id, &peer->id), "reply_channel_range %u+%u (of %u+%u) %zu scids",
first_blocknum, number_of_blocks, first_blocknum, number_of_blocks,
peer->range_first_blocknum, peer->range_first_blocknum,
peer->range_end_blocknum - peer->range_first_blocknum, peer->range_end_blocknum - peer->range_first_blocknum,
tal_count(scids)); tal_count(scids));
/* BOLT #7: /* BOLT #7:
* *
@ -1030,8 +1029,9 @@ bool query_channel_range(struct daemon *daemon,
tlvs->query_option->query_option_flags = qflags; tlvs->query_option->query_option_flags = qflags;
} else } else
tlvs = NULL; tlvs = NULL;
status_debug("sending query_channel_range for blocks %u+%u", status_peer_debug(&peer->id,
first_blocknum, number_of_blocks); "sending query_channel_range for blocks %u+%u",
first_blocknum, number_of_blocks);
msg = towire_query_channel_range(NULL, &daemon->chain_hash, msg = towire_query_channel_range(NULL, &daemon->chain_hash,
first_blocknum, number_of_blocks, first_blocknum, number_of_blocks,

199
gossipd/routing.c
View File

@ -533,10 +533,10 @@ static void bad_gossip_order(const u8 *msg,
const struct peer *peer, const struct peer *peer,
const char *details) const char *details)
{ {
status_debug("Bad gossip order from %s: %s before announcement %s", status_peer_debug(peer ? &peer->id : NULL,
peer ? type_to_string(tmpctx, struct node_id, &peer->id) "Bad gossip order: %s before announcement %s",
: "unknown", wire_type_name(fromwire_peektype(msg)), wire_type_name(fromwire_peektype(msg)),
details); details);
} }
static void destroy_local_chan(struct local_chan *local_chan, static void destroy_local_chan(struct local_chan *local_chan,
@ -1714,11 +1714,12 @@ u8 *handle_channel_announcement(struct routing_state *rstate,
* anyway. */ * anyway. */
if (current_blockheight != 0 if (current_blockheight != 0
&& short_channel_id_blocknum(&pending->short_channel_id) > current_blockheight) { && short_channel_id_blocknum(&pending->short_channel_id) > current_blockheight) {
status_debug("Ignoring future channel_announcment for %s" status_peer_debug(peer ? &peer->id : NULL,
" (current block %u)", "Ignoring future channel_announcment for %s"
type_to_string(tmpctx, struct short_channel_id, " (current block %u)",
&pending->short_channel_id), type_to_string(tmpctx, struct short_channel_id,
current_blockheight); &pending->short_channel_id),
current_blockheight);
goto ignored; goto ignored;
} }
@ -1771,7 +1772,7 @@ u8 *handle_channel_announcement(struct routing_state *rstate,
*/ */
if (!bitcoin_blkid_eq(&chain_hash, if (!bitcoin_blkid_eq(&chain_hash,
&rstate->chainparams->genesis_blockhash)) { &rstate->chainparams->genesis_blockhash)) {
status_debug( status_peer_debug(peer ? &peer->id : NULL,
"Received channel_announcement %s for unknown chain %s", "Received channel_announcement %s for unknown chain %s",
type_to_string(pending, struct short_channel_id, type_to_string(pending, struct short_channel_id,
&pending->short_channel_id), &pending->short_channel_id),
@ -1808,16 +1809,18 @@ u8 *handle_channel_announcement(struct routing_state *rstate,
> 100000) { > 100000) {
static bool warned = false; static bool warned = false;
if (!warned) { if (!warned) {
status_unusual("Flooded by channel_announcements:" status_peer_unusual(peer ? &peer->id : NULL,
" ignoring some"); "Flooded by channel_announcements:"
" ignoring some");
warned = true; warned = true;
} }
goto ignored; goto ignored;
} }
status_debug("Received channel_announcement for channel %s", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct short_channel_id, "Received channel_announcement for channel %s",
&pending->short_channel_id)); type_to_string(tmpctx, struct short_channel_id,
&pending->short_channel_id));
/* Add both endpoints to the pending_node_map so we can stash /* Add both endpoints to the pending_node_map so we can stash
* node_announcements while we wait for the txout check */ * 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); err = handle_channel_update(rstate, cupdate, peer, NULL);
if (err) { if (err) {
/* FIXME: We could send this error back to peer if != NULL */ /* FIXME: We could send this error back to peer if != NULL */
status_debug("Pending channel_update for %s from %s: %s", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct short_channel_id, scid), "Pending channel_update for %s: %s",
peer type_to_string(tmpctx, struct short_channel_id,
? type_to_string(tmpctx, struct node_id, &peer->id) scid),
: "unknown", sanitize_error(tmpctx, err, NULL));
sanitize_error(tmpctx, err, NULL));
tal_free(err); tal_free(err);
} }
} }
@ -1876,11 +1878,14 @@ bool handle_pending_cannouncement(struct daemon *daemon,
{ {
const u8 *s; const u8 *s;
struct pending_cannouncement *pending; struct pending_cannouncement *pending;
const struct node_id *src;
pending = find_pending_cannouncement(rstate, scid); pending = find_pending_cannouncement(rstate, scid);
if (!pending) if (!pending)
return false; return false;
src = pending->peer_softref ? &pending->peer_softref->id : NULL;
/* BOLT #7: /* BOLT #7:
* *
* The receiving node: * The receiving node:
@ -1889,9 +1894,11 @@ bool handle_pending_cannouncement(struct daemon *daemon,
* - MUST ignore the message. * - MUST ignore the message.
*/ */
if (tal_count(outscript) == 0) { if (tal_count(outscript) == 0) {
status_debug("channel_announcement: no unspent txout %s", status_peer_debug(src,
type_to_string(pending, struct short_channel_id, "channel_announcement: no unspent txout %s",
scid)); type_to_string(pending,
struct short_channel_id,
scid));
tal_free(pending); tal_free(pending);
add_to_txout_failures(rstate, scid); add_to_txout_failures(rstate, scid);
return false; return false;
@ -1912,10 +1919,13 @@ bool handle_pending_cannouncement(struct daemon *daemon,
&pending->bitcoin_key_2)); &pending->bitcoin_key_2));
if (!scripteq(s, outscript)) { if (!scripteq(s, outscript)) {
status_debug("channel_announcement: txout %s expectes %s, got %s", status_peer_debug(src,
type_to_string(pending, struct short_channel_id, "channel_announcement: txout %s expected %s, got %s",
scid), type_to_string(
tal_hex(tmpctx, s), tal_hex(tmpctx, outscript)); pending, struct short_channel_id,
scid),
tal_hex(tmpctx, s),
tal_hex(tmpctx, outscript));
tal_free(pending); tal_free(pending);
return false; return false;
} }
@ -1927,8 +1937,9 @@ bool handle_pending_cannouncement(struct daemon *daemon,
/* Can fail if channel_announcement too old */ /* Can fail if channel_announcement too old */
if (!routing_add_channel_announcement(rstate, pending->announce, sat, 0, if (!routing_add_channel_announcement(rstate, pending->announce, sat, 0,
pending->peer_softref)) pending->peer_softref))
status_unusual("Could not add channel_announcement %s: too old?", status_peer_unusual(src,
tal_hex(tmpctx, pending->announce)); "Could not add channel_announcement %s: too old?",
tal_hex(tmpctx, pending->announce));
else { else {
/* Did we have an update waiting? If so, apply now. */ /* Did we have an update waiting? If so, apply now. */
process_pending_channel_update(daemon, rstate, scid, pending->updates[0], 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->update_timestamps[direction] < timestamp) {
if (pending->updates[direction]) { if (pending->updates[direction]) {
status_debug("Replacing existing update"); status_peer_debug(peer ? &peer->id : NULL,
"Replacing existing update");
tal_free(pending->updates[direction]); tal_free(pending->updates[direction]);
} }
pending->updates[direction] = tal_dup_arr(pending, u8, update, tal_count(update), 0); 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 { } else {
/* If not indicated, set htlc_max_msat to channel capacity */ /* If not indicated, set htlc_max_msat to channel capacity */
if (!amount_sat_to_msat(&htlc_maximum, sat)) { if (!amount_sat_to_msat(&htlc_maximum, sat)) {
status_broken("Channel capacity %s overflows!", status_peer_broken(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct amount_sat, "Channel capacity %s overflows!",
&sat)); type_to_string(tmpctx, struct amount_sat,
&sat));
return false; return false;
} }
} }
/* Check timestamp is sane (unless from store). */ /* Check timestamp is sane (unless from store). */
if (!index && !timestamp_reasonable(rstate, timestamp)) { if (!index && !timestamp_reasonable(rstate, timestamp)) {
status_debug("Ignoring update timestamp %u for %s/%u", status_peer_debug(peer ? &peer->id : NULL,
timestamp, "Ignoring update timestamp %u for %s/%u",
type_to_string(tmpctx, timestamp,
struct short_channel_id, type_to_string(tmpctx,
&short_channel_id), struct short_channel_id,
direction); &short_channel_id),
direction);
return false; return false;
} }
@ -2101,12 +2115,14 @@ bool routing_add_channel_update(struct routing_state *rstate,
/* Allow redundant updates once every 7 days */ /* Allow redundant updates once every 7 days */
if (timestamp < hc->bcast.timestamp + GOSSIP_PRUNE_INTERVAL(rstate->dev_fast_gossip_prune) / 2 if (timestamp < hc->bcast.timestamp + GOSSIP_PRUNE_INTERVAL(rstate->dev_fast_gossip_prune) / 2
&& !cupdate_different(rstate->gs, hc, update)) { && !cupdate_different(rstate->gs, hc, update)) {
status_debug("Ignoring redundant update for %s/%u" status_peer_debug(peer ? &peer->id : NULL,
" (last %u, now %u)", "Ignoring redundant update for %s/%u"
type_to_string(tmpctx, " (last %u, now %u)",
struct short_channel_id, type_to_string(tmpctx,
&short_channel_id), struct short_channel_id,
direction, hc->bcast.timestamp, timestamp); &short_channel_id),
direction,
hc->bcast.timestamp, timestamp);
/* Ignoring != failing */ /* Ignoring != failing */
return true; return true;
} }
@ -2114,12 +2130,14 @@ bool routing_add_channel_update(struct routing_state *rstate,
/* Make sure it's not spamming us. */ /* Make sure it's not spamming us. */
if (!ratelimit(rstate, if (!ratelimit(rstate,
&hc->tokens, hc->bcast.timestamp, timestamp)) { &hc->tokens, hc->bcast.timestamp, timestamp)) {
status_debug("Ignoring spammy update for %s/%u" status_peer_debug(peer ? &peer->id : NULL,
" (last %u, now %u)", "Ignoring spammy update for %s/%u"
type_to_string(tmpctx, " (last %u, now %u)",
struct short_channel_id, type_to_string(tmpctx,
&short_channel_id), struct short_channel_id,
direction, hc->bcast.timestamp, timestamp); &short_channel_id),
direction,
hc->bcast.timestamp, timestamp);
/* Ignoring != failing */ /* Ignoring != failing */
return true; return true;
} }
@ -2285,9 +2303,10 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update TAKES,
*/ */
if (!bitcoin_blkid_eq(&chain_hash, if (!bitcoin_blkid_eq(&chain_hash,
&rstate->chainparams->genesis_blockhash)) { &rstate->chainparams->genesis_blockhash)) {
status_debug("Received channel_update for unknown chain %s", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct bitcoin_blkid, "Received channel_update for unknown chain %s",
&chain_hash)); type_to_string(tmpctx, struct bitcoin_blkid,
&chain_hash));
return NULL; 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 */ /* If we have an unvalidated channel, just queue on that */
pending = find_pending_cannouncement(rstate, &short_channel_id); pending = find_pending_cannouncement(rstate, &short_channel_id);
if (pending) { if (pending) {
status_debug("Updated pending announce with update %s/%u", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, "Updated pending announce with update %s/%u",
struct short_channel_id, type_to_string(tmpctx,
&short_channel_id), struct short_channel_id,
direction); &short_channel_id),
direction);
update_pending(pending, timestamp, serialized, direction, peer); update_pending(pending, timestamp, serialized, direction, peer);
return NULL; return NULL;
} }
@ -2337,13 +2357,12 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update TAKES,
return err; return err;
} }
status_debug("Received channel_update for channel %s/%d now %s (from %s)", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct short_channel_id, "Received channel_update for channel %s/%d now %s",
&short_channel_id), type_to_string(tmpctx, struct short_channel_id,
channel_flags & 0x01, &short_channel_id),
channel_flags & ROUTING_FLAGS_DISABLED ? "DISABLED" : "ACTIVE", channel_flags & 0x01,
peer ? type_to_string(tmpctx, struct node_id, &peer->id) channel_flags & ROUTING_FLAGS_DISABLED ? "DISABLED" : "ACTIVE");
: "unknown");
routing_add_channel_update(rstate, take(serialized), 0, peer); routing_add_channel_update(rstate, take(serialized), 0, peer);
return NULL; return NULL;
@ -2411,8 +2430,10 @@ bool routing_add_node_announcement(struct routing_state *rstate,
/* Only log this if *not* loading from store. */ /* Only log this if *not* loading from store. */
if (!index) if (!index)
status_debug("Received node_announcement for node %s", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct node_id, &node_id)); "Received node_announcement for node %s",
type_to_string(tmpctx, struct node_id,
&node_id));
node = get_node(rstate, &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 */ /* Allow redundant updates once every 7 days */
if (timestamp < node->bcast.timestamp + GOSSIP_PRUNE_INTERVAL(rstate->dev_fast_gossip_prune) / 2 if (timestamp < node->bcast.timestamp + GOSSIP_PRUNE_INTERVAL(rstate->dev_fast_gossip_prune) / 2
&& !nannounce_different(rstate->gs, node, msg)) { && !nannounce_different(rstate->gs, node, msg)) {
status_debug("Ignoring redundant nannounce for %s" status_peer_debug(peer ? &peer->id : NULL,
" (last %u, now %u)", "Ignoring redundant nannounce for %s"
type_to_string(tmpctx, " (last %u, now %u)",
struct node_id, type_to_string(tmpctx,
&node_id), struct node_id,
node->bcast.timestamp, timestamp); &node_id),
node->bcast.timestamp, timestamp);
/* Ignoring != failing */ /* Ignoring != failing */
return true; return true;
} }
@ -2483,12 +2505,13 @@ bool routing_add_node_announcement(struct routing_state *rstate,
/* Make sure it's not spamming us. */ /* Make sure it's not spamming us. */
if (!ratelimit(rstate, if (!ratelimit(rstate,
&node->tokens, node->bcast.timestamp, timestamp)) { &node->tokens, node->bcast.timestamp, timestamp)) {
status_debug("Ignoring spammy nannounce for %s" status_peer_debug(peer ? &peer->id : NULL,
" (last %u, now %u)", "Ignoring spammy nannounce for %s"
type_to_string(tmpctx, " (last %u, now %u)",
struct node_id, type_to_string(tmpctx,
&node_id), struct node_id,
node->bcast.timestamp, timestamp); &node_id),
node->bcast.timestamp, timestamp);
/* Ignoring != failing */ /* Ignoring != failing */
return true; return true;
} }
@ -2868,6 +2891,7 @@ void route_prune(struct routing_state *rstate)
} }
bool handle_local_add_channel(struct routing_state *rstate, bool handle_local_add_channel(struct routing_state *rstate,
const struct peer *peer,
const u8 *msg, u64 index) const u8 *msg, u64 index)
{ {
struct short_channel_id scid; 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, if (!fromwire_gossipd_local_add_channel(msg, &scid, &remote_node_id,
&sat)) { &sat)) {
status_broken("Unable to parse local_add_channel message: %s", status_peer_broken(peer ? &peer->id : NULL,
tal_hex(msg, msg)); "Unable to parse local_add_channel message: %s",
tal_hex(msg, msg));
return false; return false;
} }
/* Can happen on channeld restart. */ /* Can happen on channeld restart. */
if (get_channel(rstate, &scid)) { 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; return true;
} }
status_debug("local_add_channel %s", status_peer_debug(peer ? &peer->id : NULL,
type_to_string(tmpctx, struct short_channel_id, &scid)); "local_add_channel %s",
type_to_string(tmpctx, struct short_channel_id, &scid));
/* Create new (unannounced) channel */ /* Create new (unannounced) channel */
chan = new_chan(rstate, &scid, &rstate->local_id, &remote_node_id, sat); chan = new_chan(rstate, &scid, &rstate->local_id, &remote_node_id, sat);

4
gossipd/routing.h
View File

@ -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 * is the case for private channels or channels that have not yet reached
* `announce_depth`. * `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); u64 index);
/** /**

44
gossipd/seeker.c
View File

@ -126,11 +126,9 @@ static void set_state_(struct seeker *seeker, enum seeker_state state,
{ {
va_list ap; va_list ap;
va_start(ap, fmt); va_start(ap, fmt);
status_debug("seeker: state = %s %s%s %s", status_peer_debug(peer ? &peer->id : NULL,
statename, peer ? "from " : "", "seeker: state = %s %s",
peer ? type_to_string(tmpctx, struct node_id, &peer->id) statename, tal_vfmt(tmpctx, fmt, ap));
: "",
tal_vfmt(tmpctx, fmt, ap));
va_end(ap); va_end(ap);
seeker->state = state; seeker->state = state;
selected_peer(seeker, peer); selected_peer(seeker, peer);
@ -202,8 +200,7 @@ static void disable_gossip_stream(struct seeker *seeker, struct peer *peer)
{ {
u8 *msg; u8 *msg;
status_debug("seeker: disabling gossip from %s", status_peer_debug(&peer->id, "seeker: disabling gossip");
type_to_string(tmpctx, struct node_id, &peer->id));
/* This is allowed even if they don't understand it (odd) */ /* This is allowed even if they don't understand it (odd) */
msg = towire_gossip_timestamp_filter(NULL, msg = towire_gossip_timestamp_filter(NULL,
@ -230,8 +227,7 @@ static void enable_gossip_stream(struct seeker *seeker, struct peer *peer)
else else
start = 0; start = 0;
status_debug("seeker: starting gossip from %s", status_peer_debug(&peer->id, "seeker: starting gossip");
type_to_string(tmpctx, struct node_id, &peer->id));
/* This is allowed even if they don't understand it (odd) */ /* This is allowed even if they don't understand it (odd) */
msg = towire_gossip_timestamp_filter(NULL, 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 */ /* We have selected this peer to stream us startup gossip */
static void peer_gossip_startup(struct seeker *seeker, struct peer *peer) static void peer_gossip_startup(struct seeker *seeker, struct peer *peer)
{ {
status_debug("seeker: startup peer is %s", status_peer_debug(&peer->id, "seeker: chosen as startup peer");
type_to_string(tmpctx, struct node_id, &peer->id));
selected_peer(seeker, peer); selected_peer(seeker, peer);
normal_gossip_start(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. */ /* We might have given up on them, then they replied. */
if (seeker->random_peer_softref != peer) { if (seeker->random_peer_softref != peer) {
status_debug("seeker: belated reply from %s: ignoring", status_peer_debug(&peer->id, "seeker: belated reply: ignoring");
type_to_string(tmpctx, struct node_id, &peer->id));
return; return;
} }
@ -542,8 +536,9 @@ static void nodeannounce_query_done(struct peer *peer, bool complete)
new_nannounce++; new_nannounce++;
} }
status_debug("seeker: found %zu new node_announcements in %zu scids", status_peer_debug(&peer->id,
new_nannounce, num_scids); "seeker: found %zu new node_announcements in %zu scids",
new_nannounce, num_scids);
seeker->nannounce_scids = tal_free(seeker->nannounce_scids); seeker->nannounce_scids = tal_free(seeker->nannounce_scids);
seeker->nannounce_query_flags = tal_free(seeker->nannounce_query_flags); seeker->nannounce_query_flags = tal_free(seeker->nannounce_query_flags);
@ -780,7 +775,7 @@ static void check_firstpeer(struct seeker *seeker)
return; return;
/* Other peers can gossip now. */ /* 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); clear_softref(seeker, &seeker->random_peer_softref);
list_for_each(&seeker->daemon->peers, p, list) { list_for_each(&seeker->daemon->peers, p, list) {
if (p == peer) if (p == peer)
@ -812,9 +807,9 @@ static void check_probe(struct seeker *seeker,
if (peer_made_progress(seeker)) if (peer_made_progress(seeker))
return; return;
status_debug("Peer %s has only moved gossip %zu->%zu for probe, giving up on it", status_peer_debug(&peer->id,
type_to_string(tmpctx, struct node_id, &peer->id), "has only moved gossip %zu->%zu for probe, giving up on it",
seeker->prev_gossip_count, peer->gossip_counter); seeker->prev_gossip_count, peer->gossip_counter);
clear_softref(seeker, &seeker->random_peer_softref); clear_softref(seeker, &seeker->random_peer_softref);
restart(seeker); restart(seeker);
} }
@ -845,15 +840,14 @@ static void maybe_rotate_gossipers(struct seeker *seeker)
/* If we have a slot free, or ~ 1 per hour */ /* If we have a slot free, or ~ 1 per hour */
for (i = 0; i < ARRAY_SIZE(seeker->gossiper_softref); i++) { for (i = 0; i < ARRAY_SIZE(seeker->gossiper_softref); i++) {
if (!seeker->gossiper_softref[i]) { if (!seeker->gossiper_softref[i]) {
status_debug("seeker: filling slot %zu with %s", status_peer_debug(&peer->id, "seeker: filling slot %zu",
i, type_to_string(tmpctx, struct node_id, i);
&peer->id));
goto set_gossiper; goto set_gossiper;
} }
if (pseudorand(ARRAY_SIZE(seeker->gossiper_softref) * 60) == 0) { if (pseudorand(ARRAY_SIZE(seeker->gossiper_softref) * 60) == 0) {
status_debug("seeker: replacing slot %zu with %s", status_peer_debug(&peer->id,
i, type_to_string(tmpctx, struct node_id, "seeker: replacing slot %zu",
&peer->id)); i);
goto clear_and_set_gossiper; goto clear_and_set_gossiper;
} }
} }

2
gossipd/test/run-find_route-specific.c
View File

@ -9,7 +9,7 @@
#include <stdio.h> #include <stdio.h>
#define status_fmt(level, node_id, fmt, ...) \ #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 "../routing.c"
#include "../gossip_store.c" #include "../gossip_store.c"

2
tests/test_connection.py
View File

@ -235,7 +235,7 @@ def test_disconnect(node_factory):
# Should have 3 connect fails. # Should have 3 connect fails.
for d in disconnects: 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'])) .format(l2.info['id']))
# Should still only have one peer! # Should still only have one peer!