gossip: Reduce verbosity

Now we only report serious failures, or messages that actually changed
the local view.

Signed-off-by: Christian Decker <decker.christian@gmail.com>

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

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")
@@ -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',
+        # Just wait for the update to kick off and then check the effect
-                                 'peer_in WIRE_CHANNEL_ANNOUNCEMENT',
+        needle = "Received channel_update for channel"
-                                 'Channel {}\\(0\\) was updated.'
+        l1.daemon.wait_for_log(needle)
-                                 .format(channel_id),
+        l2.daemon.wait_for_log(needle)
-                                 'Channel {}\\(1\\) was updated.'
+        wait_for(lambda: len(l1.getactivechannels()) == 2)
-                                 .format(channel_id)])
 
         nodes = l1.rpc.listnodes()['nodes']
         assert set([n['nodeid'] for n in nodes]) == set([l1.info['id'], l2.info['id']])
@@ -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']))
+        l1.daemon.wait_for_logs(['Received channel_update for channel 434:1:1.1.',
-        l2.daemon.wait_for_log('Received node_announcement for node {}'.format(l1.info['id']))
+                                 '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")