diff --git a/gossipd/routing.c b/gossipd/routing.c index c6b139254..c26395309 100644 --- a/gossipd/routing.c +++ b/gossipd/routing.c @@ -220,7 +220,7 @@ get_or_make_connection(struct routing_state *rstate, } } - status_trace("Creating new route from %s to %s", + SUPERVERBOSE("Creating new route from %s to %s", type_to_string(trc, struct pubkey, &from->id), type_to_string(trc, struct pubkey, &to->id)); @@ -851,13 +851,8 @@ void handle_channel_update(struct routing_state *rstate, const u8 *update) return; } - status_trace("Received channel_update for channel %s(%d)", - type_to_string(trc, struct short_channel_id, - &short_channel_id), - flags & 0x01); - if (update_to_pending(rstate, &short_channel_id, serialized, direction)) { - status_trace("Deferring update for pending channel %s(%d)", + SUPERVERBOSE("Deferring update for pending channel %s(%d)", type_to_string(trc, struct short_channel_id, &short_channel_id), direction); tal_free(tmpctx); @@ -867,13 +862,13 @@ void handle_channel_update(struct routing_state *rstate, const u8 *update) c = get_connection_by_scid(rstate, &short_channel_id, direction); if (!c) { - status_trace("Ignoring update for unknown channel %s", + SUPERVERBOSE("Ignoring update for unknown channel %s", type_to_string(trc, struct short_channel_id, &short_channel_id)); tal_free(tmpctx); return; } else if (c->last_timestamp >= timestamp) { - status_trace("Ignoring outdated update."); + SUPERVERBOSE("Ignoring outdated update."); tal_free(tmpctx); return; } else if (!check_channel_update(&c->src->id, &signature, serialized)) { @@ -882,7 +877,11 @@ void handle_channel_update(struct routing_state *rstate, const u8 *update) return; } - //FIXME(cdecker) Check signatures + status_trace("Received channel_update for channel %s(%d)", + type_to_string(trc, struct short_channel_id, + &short_channel_id), + flags & 0x01); + c->last_timestamp = timestamp; c->delay = expiry; c->htlc_minimum_msat = htlc_minimum_msat; @@ -890,7 +889,7 @@ void handle_channel_update(struct routing_state *rstate, const u8 *update) c->proportional_fee = fee_proportional_millionths; c->active = (flags & ROUTING_FLAGS_DISABLED) == 0; c->unroutable_until = 0; - status_trace("Channel %s(%d) was updated.", + SUPERVERBOSE("Channel %s(%d) was updated.", type_to_string(trc, struct short_channel_id, &short_channel_id), direction); @@ -984,15 +983,13 @@ void handle_node_announcement( * and MAY discard the message altogether. */ if (unsupported_features(features, NULL)) { - status_trace("Ignoring node announcement, unsupported features %s.", + status_trace("Ignoring node announcement for node %s, unsupported features %s.", + type_to_string(tmpctx, struct pubkey, &node_id), tal_hex(tmpctx, features)); tal_free(tmpctx); return; } - status_trace("Received node_announcement for node %s", - type_to_string(trc, struct pubkey, &node_id)); - sha256_double(&hash, serialized + 66, tal_count(serialized) - 66); if (!check_signed_hash(&hash, &signature, &node_id)) { status_trace("Ignoring node announcement, signature verification failed."); @@ -1002,15 +999,21 @@ void handle_node_announcement( node = get_node(rstate, &node_id); if (!node) { - status_trace("Node not found, was the node_announcement preceded by at least channel_announcement?"); + SUPERVERBOSE("Node not found, was the node_announcement for " + "node %s preceded by at least " + "channel_announcement?", + type_to_string(tmpctx, struct pubkey, &node_id)); tal_free(tmpctx); return; } else if (node->last_timestamp >= timestamp) { - status_trace("Ignoring node announcement, it's outdated."); + SUPERVERBOSE("Ignoring node announcement, it's outdated."); tal_free(tmpctx); return; } + status_trace("Received node_announcement for node %s", + type_to_string(tmpctx, struct pubkey, &node_id)); + wireaddrs = read_addresses(tmpctx, addresses); if (!wireaddrs) { status_trace("Unable to parse addresses."); diff --git a/tests/test_lightningd.py b/tests/test_lightningd.py index a189ababd..46e722437 100644 --- a/tests/test_lightningd.py +++ b/tests/test_lightningd.py @@ -325,9 +325,9 @@ class LightningDTests(BaseLightningDTests): def wait_for_routes(self, l1, channel_ids): bitcoind.generate_block(5) # Could happen in any order... - l1.daemon.wait_for_logs(['Channel {}\\(0\\) was updated'.format(c) + l1.daemon.wait_for_logs(['Received channel_update for channel {}\\(0\\)'.format(c) for c in channel_ids] - + ['Channel {}\\(1\\) was updated'.format(c) + + ['Received channel_update for channel {}\\(1\\)'.format(c) for c in channel_ids]) @unittest.skipIf(not DEVELOPER, "needs DEVELOPER=1") @@ -1180,7 +1180,7 @@ class LightningDTests(BaseLightningDTests): l1.rpc.withdraw(l1.rpc.newaddr()['address'], 'all') bitcoind.generate_block(1) l1.daemon.wait_for_log("but we don't care") - + # And lightningd should respect that! assert not l1.daemon.is_in_log("Can't unwatch txid") @@ -1197,7 +1197,7 @@ class LightningDTests(BaseLightningDTests): # Note: for this test we leave onchaind running, so we can detect # any leaks! - + @unittest.skipIf(not DEVELOPER, "needs DEVELOPER=1") def test_onchain_dust_out(self): """Onchain handling of outgoing dust htlcs (they should fail)""" @@ -1672,20 +1672,12 @@ class LightningDTests(BaseLightningDTests): 'peer_in WIRE_ANNOUNCEMENT_SIGNATURES']) channel_id = channels[0]['short_channel_id'] - # Could happen in any order. - l1.daemon.wait_for_logs(['peer_out WIRE_CHANNEL_ANNOUNCEMENT', - 'peer_in WIRE_CHANNEL_ANNOUNCEMENT', - 'Channel {}\\(0\\) was updated.' - .format(channel_id), - 'Channel {}\\(1\\) was updated.' - .format(channel_id)]) - - l2.daemon.wait_for_logs(['peer_out WIRE_CHANNEL_ANNOUNCEMENT', - 'peer_in WIRE_CHANNEL_ANNOUNCEMENT', - 'Channel {}\\(0\\) was updated.' - .format(channel_id), - 'Channel {}\\(1\\) was updated.' - .format(channel_id)]) + + # Just wait for the update to kick off and then check the effect + needle = "Received channel_update for channel" + l1.daemon.wait_for_log(needle) + l2.daemon.wait_for_log(needle) + wait_for(lambda: len(l1.getactivechannels()) == 2) nodes = l1.rpc.listnodes()['nodes'] assert set([n['nodeid'] for n in nodes]) == set([l1.info['id'], l2.info['id']]) @@ -2641,7 +2633,7 @@ class LightningDTests(BaseLightningDTests): c = db.cursor() c.execute('SELECT COUNT(*) FROM outputs WHERE status=0') assert(c.fetchone()[0] == 1) - + out = l1.rpc.withdraw(waddr, 'all') c = db.cursor() c.execute('SELECT COUNT(*) FROM outputs WHERE status=0') @@ -2754,7 +2746,7 @@ class LightningDTests(BaseLightningDTests): # All should be good. l1.daemon.wait_for_log(' to CHANNELD_NORMAL') l2.daemon.wait_for_log(' to CHANNELD_NORMAL') - + def test_addfunds_from_block(self): """Send funds to the daemon without telling it explicitly """ @@ -3083,8 +3075,10 @@ class LightningDTests(BaseLightningDTests): l2.daemon.start() # Now they should sync and re-establish again - l1.daemon.wait_for_log('Received node_announcement for node {}'.format(l2.info['id'])) - l2.daemon.wait_for_log('Received node_announcement for node {}'.format(l1.info['id'])) + l1.daemon.wait_for_logs(['Received channel_update for channel 434:1:1.1.', + 'Received channel_update for channel 434:1:1.0.']) + l2.daemon.wait_for_logs(['Received channel_update for channel 434:1:1.1.', + 'Received channel_update for channel 434:1:1.0.']) wait_for(lambda: [c['active'] for c in l1.rpc.listchannels()['channels']] == [True, True]) @unittest.skipIf(not DEVELOPER, "needs DEVELOPER=1")