From 8ee60e2d8ed12507a9ad3dd5acf096d16e94bae8 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Thu, 17 May 2018 14:39:59 +0930 Subject: [PATCH] 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 --- gossipd/routing.c | 27 ++++++++++++++++++-------- gossipd/test/run-bench-find_route.c | 6 ++++++ gossipd/test/run-find_route-specific.c | 6 ++++++ gossipd/test/run-find_route.c | 6 ++++++ tests/fixtures.py | 10 ++++++++++ tests/test_lightningd.py | 12 ++++++++++++ 6 files changed, 59 insertions(+), 8 deletions(-) diff --git a/gossipd/routing.c b/gossipd/routing.c index 11336a6a9..86dc45207 100644 --- a/gossipd/routing.c +++ b/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); } diff --git a/gossipd/test/run-bench-find_route.c b/gossipd/test/run-bench-find_route.c index e5ecf32ca..d98d9b01c 100644 --- a/gossipd/test/run-bench-find_route.c +++ b/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. */ diff --git a/gossipd/test/run-find_route-specific.c b/gossipd/test/run-find_route-specific.c index aef9e2afd..776684aaf 100644 --- a/gossipd/test/run-find_route-specific.c +++ b/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; diff --git a/gossipd/test/run-find_route.c b/gossipd/test/run-find_route.c index f8d74568d..45e488a7f 100644 --- a/gossipd/test/run-find_route.c +++ b/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. */ diff --git a/tests/fixtures.py b/tests/fixtures.py index 5b939e920..cad551ff1 100644 --- a/tests/fixtures.py +++ b/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) diff --git a/tests/test_lightningd.py b/tests/test_lightningd.py index d1f902899..5b128807c 100644 --- a/tests/test_lightningd.py +++ b/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")