Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

gossipd: Make gossipd shut up #3981

Merged
merged 6 commits into from
Aug 27, 2020
Merged

gossipd: Make gossipd shut up #3981

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
adf4f9d
pytest: Stabilize test_onchaind_replay
cdecker Aug 25, 2020
5b00517
pyln-testing: Poll for channel active instead of watching logs
cdecker Aug 25, 2020
c26225f
pyln-testing: Have LightningNode.fund_channel poll
cdecker Aug 25, 2020
7f4c46e
pytest: Stabilize test_pay_get_error_with_update
cdecker Aug 25, 2020
e7ae97d
pytest: Stabilize test_onchain_middleman
cdecker Aug 26, 2020
7c2a9f1
gossipd: Make gossipd much quieter
cdecker Aug 10, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
47 changes: 9 additions & 38 deletions contrib/pyln-testing/pyln/testing/utils.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -759,18 +759,9 @@ def fund_channel(self, l2, amount, wait_for_active=True, announce_channel=True):
get_tx_p2wsh_outnum(self.bitcoin, tx, amount))

if wait_for_active:
# We wait until gossipd sees both local updates, as well as status NORMAL,
# so it can definitely route through.
self.daemon.wait_for_logs([r'update for channel {}/0 now ACTIVE'
.format(scid),
r'update for channel {}/1 now ACTIVE'
.format(scid),
'to CHANNELD_NORMAL'])
l2.daemon.wait_for_logs([r'update for channel {}/0 now ACTIVE'
.format(scid),
r'update for channel {}/1 now ACTIVE'
.format(scid),
'to CHANNELD_NORMAL'])
self.wait_channel_active(scid)
l2.wait_channel_active(scid)

return scid

def subd_pid(self, subd, peerid=None):
Expand Down Expand Up @@ -1139,40 +1130,20 @@ def join_nodes(self, nodes, fundchannel=True, fundamount=10**6, wait_for_announc
scid = src.get_channel_scid(dst)
scids.append(scid)

# We don't want to assume message order here.
# Wait for ends:
nodes[0].daemon.wait_for_logs([r'update for channel {}/0 now ACTIVE'
.format(scids[0]),
r'update for channel {}/1 now ACTIVE'
.format(scids[0])])
nodes[-1].daemon.wait_for_logs([r'update for channel {}/0 now ACTIVE'
.format(scids[-1]),
r'update for channel {}/1 now ACTIVE'
.format(scids[-1])])
# Now wait for intermediate nodes:
for i, n in enumerate(nodes[1:-1]):
n.daemon.wait_for_logs([r'update for channel {}/0 now ACTIVE'
.format(scids[i]),
r'update for channel {}/1 now ACTIVE'
.format(scids[i]),
r'update for channel {}/0 now ACTIVE'
.format(scids[i + 1]),
r'update for channel {}/1 now ACTIVE'
.format(scids[i + 1])])
# Wait for all channels to be active (locally)
for i, n in enumerate(scids):
nodes[i].wait_channel_active(scids[i])
nodes[i + 1].wait_channel_active(scids[i])

if not wait_for_announce:
return

bitcoind.generate_block(5)

def both_dirs_ready(n, scid):
resp = n.rpc.listchannels(scid)
return [a['active'] for a in resp['channels']] == [True, True]

# Make sure everyone sees all channels: we can cheat and
# simply check the ends (since it's a line).
wait_for(lambda: both_dirs_ready(nodes[0], scids[-1]))
wait_for(lambda: both_dirs_ready(nodes[-1], scids[0]))
nodes[0].wait_channel_active(scids[-1])
nodes[-1].wait_channel_active(scids[0])

# Make sure we have all node announcements, too (just check ends)
for n in nodes:
Expand Down
68 changes: 32 additions & 36 deletions gossipd/routing.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2090,13 +2090,11 @@ bool routing_add_channel_update(struct routing_state *rstate,

/* Check timestamp is sane (unless from store). */
if (!index && !timestamp_reasonable(rstate, timestamp)) {
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);
SUPERVERBOSE("Ignoring update timestamp %u for %s/%u",
timestamp,
type_to_string(tmpctx, struct short_channel_id,
&short_channel_id),
direction);
return false;
}

Expand Down Expand Up @@ -2127,14 +2125,12 @@ 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_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);
SUPERVERBOSE("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;
}
Expand Down Expand Up @@ -2221,6 +2217,14 @@ bool routing_add_channel_update(struct routing_state *rstate,
process_pending_node_announcement(rstate, &chan->nodes[1]->id);
tal_free(uc);
}

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");

return true;
}

Expand Down Expand Up @@ -2368,13 +2372,6 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update TAKES,
return err;
}

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;
}
Expand Down Expand Up @@ -2439,13 +2436,6 @@ bool routing_add_node_announcement(struct routing_state *rstate,
return false;
}

/* Only log this if *not* loading from store. */
if (!index)
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);

if (node == NULL || !node_has_broadcastable_channels(node)) {
Expand Down Expand Up @@ -2500,13 +2490,11 @@ 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_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);
SUPERVERBOSE(
"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;
}
Expand Down Expand Up @@ -2553,6 +2541,14 @@ bool routing_add_node_announcement(struct routing_state *rstate,
NULL);
peer_supplied_good_gossip(peer, 1);
}

/* Only log this if *not* loading from store. */
if (!index)
status_peer_debug(peer ? &peer->id : NULL,
"Received node_announcement for node %s",
type_to_string(tmpctx, struct node_id,
&node_id));

return true;
}

Expand Down
4 changes: 2 additions & 2 deletions tests/test_closing.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1110,7 +1110,7 @@ def test_onchaind_replay(node_factory, bitcoind):
}
l1.rpc.sendpay([routestep], rhash)
l1.daemon.wait_for_log('sendrawtx exit 0')
bitcoind.generate_block(1)
bitcoind.generate_block(1, wait_for_mempool=1)

# Wait for nodes to notice the failure, this seach needle is after the
# DB commit so we're sure the tx entries in onchaindtxs have been added
Expand Down Expand Up @@ -1347,7 +1347,7 @@ def try_pay():

# l2 will drop to chain.
l2.daemon.wait_for_log('sendrawtx exit 0')
l1.bitcoin.generate_block(1)
l1.bitcoin.generate_block(1, wait_for_mempool=1)
l2.daemon.wait_for_log(' to ONCHAIN')
l1.daemon.wait_for_log(' to ONCHAIN')
l2.daemon.wait_for_log('OUR_UNILATERAL/THEIR_HTLC')
Expand Down
3 changes: 2 additions & 1 deletion tests/test_pay.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -295,6 +295,7 @@ def test_pay_get_error_with_update(node_factory):
# Make sure that l2 has seen disconnect, considers channel disabled.
wait_for(lambda: [c['active'] for c in l2.rpc.listchannels(chanid2)['channels']] == [False, False])

assert(l1.is_channel_active(chanid2))
l1.rpc.sendpay(route, inv['payment_hash'])
with pytest.raises(RpcError, match=r'WIRE_TEMPORARY_CHANNEL_FAILURE'):
l1.rpc.waitsendpay(inv['payment_hash'])
Expand All @@ -306,7 +307,7 @@ def test_pay_get_error_with_update(node_factory):
l1.daemon.wait_for_log(r'Extracted channel_update 0102.*from onionreply 10070088[0-9a-fA-F]{88}')

# And now monitor for l1 to apply the channel_update we just extracted
l1.daemon.wait_for_log(r'Received channel_update for channel {}/. now DISABLED'.format(chanid2))
wait_for(lambda: not l1.is_channel_active(chanid2))


@unittest.skipIf(not DEVELOPER, "needs to deactivate shadow routing")
Expand Down