testing: make sure we don't see gossip in bad order.

This is something which generally shouldn't happen, but we didn't
notice it previously.

We ignore this warning in the case where a channel was deleted: this
happens because one side can send an update while the other notices
that the channel is closed.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

gossipd/routing.c

@@ -201,6 +201,13 @@ static void init_half_chan(struct routing_state *rstate,
 	c->last_timestamp = time_now().ts.tv_sec - rstate->prune_timeout/2;
 }
 
+static void bad_gossip_order(const u8 *msg, const char *details)
+{
+	status_trace("Bad gossip order: %s before announcement %s",
+		     wire_type_name(fromwire_peektype(msg)),
+		     details);
+}
+
 struct chan *new_chan(struct routing_state *rstate,
 		      const struct short_channel_id *scid,
 		      const struct pubkey *id1,
@@ -1015,9 +1022,12 @@ u8 *handle_channel_update(struct routing_state *rstate, const u8 *update)
 		}
 
 		if (!chan) {
-			SUPERVERBOSE("Ignoring update for unknown channel %s",
-				     type_to_string(tmpctx, struct short_channel_id,
-						    &short_channel_id));
+			bad_gossip_order(serialized,
+					 tal_fmt(tmpctx, "%s(%u)",
+						 type_to_string(tmpctx,
+							struct short_channel_id,
+							&short_channel_id),
+						 flags));
 			return NULL;
 		}
 	}
@@ -1245,11 +1255,9 @@ u8 *handle_node_announcement(struct routing_state *rstate, const u8 *node_ann)
 		pna = pending_node_map_get(rstate->pending_node_map,
 					   &node_id.pubkey);
 		if (!pna) {
-			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));
+			bad_gossip_order(serialized,
+					 type_to_string(tmpctx, struct pubkey,
+							&node_id));
 		} else if (pna->timestamp < timestamp) {
 			SUPERVERBOSE(
 			    "Deferring node_announcement for node %s",
@@ -1519,6 +1527,9 @@ void handle_local_add_channel(struct routing_state *rstate, const u8 *msg)
 		return;
 	}
 
+	status_trace("local_add_channel %s",
+		     type_to_string(tmpctx, struct short_channel_id, &scid));
+
 	/* Create new (unannounced) channel */
 	new_chan(rstate, &scid, &rstate->local_id, &remote_node_id);
 }

gossipd/test/run-bench-find_route.c

@@ -83,6 +83,9 @@ bool fromwire_gossip_store_node_announcement(const tal_t *ctx UNNEEDED, const vo
 /* Generated stub for fromwire_node_announcement */
 bool fromwire_node_announcement(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, secp256k1_ecdsa_signature *signature UNNEEDED, u8 **features UNNEEDED, u32 *timestamp UNNEEDED, struct pubkey *node_id UNNEEDED, u8 rgb_color[3] UNNEEDED, u8 alias[32] UNNEEDED, u8 **addresses UNNEEDED)
 { fprintf(stderr, "fromwire_node_announcement called!\n"); abort(); }
+/* Generated stub for fromwire_peektype */
+int fromwire_peektype(const u8 *cursor UNNEEDED)
+{ fprintf(stderr, "fromwire_peektype called!\n"); abort(); }
 /* Generated stub for fromwire_u8 */
 u8 fromwire_u8(const u8 **cursor UNNEEDED, size_t *max UNNEEDED)
 { fprintf(stderr, "fromwire_u8 called!\n"); abort(); }
@@ -123,6 +126,9 @@ u8 *towire_gossip_store_local_add_channel(const tal_t *ctx UNNEEDED, const u8 *l
 /* Generated stub for towire_gossip_store_node_announcement */
 u8 *towire_gossip_store_node_announcement(const tal_t *ctx UNNEEDED, const u8 *announcement UNNEEDED)
 { fprintf(stderr, "towire_gossip_store_node_announcement called!\n"); abort(); }
+/* Generated stub for wire_type_name */
+const char *wire_type_name(int e UNNEEDED)
+{ fprintf(stderr, "wire_type_name called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 /* Updates existing route if required. */

gossipd/test/run-find_route-specific.c

@@ -47,6 +47,9 @@ bool fromwire_gossip_store_node_announcement(const tal_t *ctx UNNEEDED, const vo
 /* Generated stub for fromwire_node_announcement */
 bool fromwire_node_announcement(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, secp256k1_ecdsa_signature *signature UNNEEDED, u8 **features UNNEEDED, u32 *timestamp UNNEEDED, struct pubkey *node_id UNNEEDED, u8 rgb_color[3] UNNEEDED, u8 alias[32] UNNEEDED, u8 **addresses UNNEEDED)
 { fprintf(stderr, "fromwire_node_announcement called!\n"); abort(); }
+/* Generated stub for fromwire_peektype */
+int fromwire_peektype(const u8 *cursor UNNEEDED)
+{ fprintf(stderr, "fromwire_peektype called!\n"); abort(); }
 /* Generated stub for fromwire_u8 */
 u8 fromwire_u8(const u8 **cursor UNNEEDED, size_t *max UNNEEDED)
 { fprintf(stderr, "fromwire_u8 called!\n"); abort(); }
@@ -87,6 +90,9 @@ u8 *towire_gossip_store_local_add_channel(const tal_t *ctx UNNEEDED, const u8 *l
 /* Generated stub for towire_gossip_store_node_announcement */
 u8 *towire_gossip_store_node_announcement(const tal_t *ctx UNNEEDED, const u8 *announcement UNNEEDED)
 { fprintf(stderr, "towire_gossip_store_node_announcement called!\n"); abort(); }
+/* Generated stub for wire_type_name */
+const char *wire_type_name(int e UNNEEDED)
+{ fprintf(stderr, "wire_type_name called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 const void *trc;

gossipd/test/run-find_route.c

@@ -45,6 +45,9 @@ bool fromwire_gossip_store_node_announcement(const tal_t *ctx UNNEEDED, const vo
 /* Generated stub for fromwire_node_announcement */
 bool fromwire_node_announcement(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, secp256k1_ecdsa_signature *signature UNNEEDED, u8 **features UNNEEDED, u32 *timestamp UNNEEDED, struct pubkey *node_id UNNEEDED, u8 rgb_color[3] UNNEEDED, u8 alias[32] UNNEEDED, u8 **addresses UNNEEDED)
 { fprintf(stderr, "fromwire_node_announcement called!\n"); abort(); }
+/* Generated stub for fromwire_peektype */
+int fromwire_peektype(const u8 *cursor UNNEEDED)
+{ fprintf(stderr, "fromwire_peektype called!\n"); abort(); }
 /* Generated stub for fromwire_u8 */
 u8 fromwire_u8(const u8 **cursor UNNEEDED, size_t *max UNNEEDED)
 { fprintf(stderr, "fromwire_u8 called!\n"); abort(); }
@@ -85,6 +88,9 @@ u8 *towire_gossip_store_local_add_channel(const tal_t *ctx UNNEEDED, const u8 *l
 /* Generated stub for towire_gossip_store_node_announcement */
 u8 *towire_gossip_store_node_announcement(const tal_t *ctx UNNEEDED, const u8 *announcement UNNEEDED)
 { fprintf(stderr, "towire_gossip_store_node_announcement called!\n"); abort(); }
+/* Generated stub for wire_type_name */
+const char *wire_type_name(int e UNNEEDED)
+{ fprintf(stderr, "wire_type_name called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
 /* Updates existing route if required. */

tests/fixtures.py

@@ -91,6 +91,10 @@ def node_factory(directory, test_name, bitcoind, executor):
         err_count += checkReconnect(node)
     if err_count:
         raise ValueError("{} nodes had unexpected reconnections".format(err_count))
+    for node in nf.nodes:
+        err_count += checkBadGossipOrder(node)
+    if err_count:
+        raise ValueError("{} nodes had bad gossip order".format(err_count))
 
     if not ok:
         raise Exception("At least one lightning exited with unexpected non-zero return code")
@@ -147,6 +151,12 @@ def checkReconnect(node):
     return 0
 
 
+def checkBadGossipOrder(node):
+    if node.daemon.is_in_log('Bad gossip order') and not node.daemon.is_in_log('Deleting channel'):
+        return 1
+    return 0
+
+
 @pytest.fixture
 def executor():
     ex = futures.ThreadPoolExecutor(max_workers=20)

tests/test_lightningd.py

@@ -299,6 +299,13 @@ class BaseLightningDTests(unittest.TestCase):
             return 1
         return 0
 
+    def checkBadGossipOrder(self, node):
+        # We can have a race where we notice a channel deleted and someone
+        # sends an update.
+        if node.daemon.is_in_log('Bad gossip order') and not node.daemon.is_in_log('Deleting channel'):
+            return 1
+        return 0
+
     def tearDown(self):
         ok = self.node_factory.killall([not n.may_fail for n in self.node_factory.nodes])
         self.executor.shutdown(wait=False)
@@ -322,6 +329,11 @@ class BaseLightningDTests(unittest.TestCase):
         if err_count:
             raise ValueError("{} nodes had unexpected reconnections".format(err_count))
 
+        for node in self.node_factory.nodes:
+            err_count += self.checkBadGossipOrder(node)
+        if err_count:
+            raise ValueError("{} nodes had bad gossip order".format(err_count))
+
         if not ok:
             raise Exception("At least one lightning exited with unexpected non-zero return code")