test_lightningd.py: fix obscure corner case in gossip.

I actually hit this very hard to reproduce race: if we haven't process
the channeld message when block #6 comes in, we won't send the gossip
message.  We wait for logs, but don't generate new blocks, and timeout
on l1.daemon.wait_for_log('peer_out WIRE_ANNOUNCEMENT_SIGNATURES').

The solution, which also tests that we don't send announcement signatures
immediately, is to generate a single block, wait for CHANNELD_NORMAL,
then (in gossip tests), generate 5 more.

Signed-off-by: Rusty Russell <[email protected]>

Author: rustyrussell

lightningd/gossip/gossip.c

@@ -612,16 +612,19 @@ static struct io_plan *resolve_channel_req(struct io_conn *conn,
 		status_failed(WIRE_GOSSIPSTATUS_BAD_REQUEST,
 			      "Unable to parse resolver request");
 
-	status_trace("Attempting to resolve channel %s",
-		     type_to_string(trc, struct short_channel_id, &scid));
-
 	nc = get_connection_by_scid(daemon->rstate, &scid, 0);
 	if (!nc) {
+		status_trace("Failed to resolve channel %s",
+			     type_to_string(trc, struct short_channel_id, &scid));
 		keys = NULL;
 	} else {
 		keys = tal_arr(msg, struct pubkey, 2);
 		keys[0] = nc->src->id;
 		keys[1] = nc->dst->id;
+		status_trace("Resolved channel %s %s<->%s",
+			     type_to_string(trc, struct short_channel_id, &scid),
+			     type_to_string(trc, struct pubkey, &keys[0]),
+			     type_to_string(trc, struct pubkey, &keys[1]));
 	}
 	daemon_conn_send(&daemon->master,
 			 take(towire_gossip_resolve_channel_reply(msg, keys)));

lightningd/peer_control.c

@@ -662,6 +662,10 @@ static enum watch_result funding_announce_cb(struct peer *peer,
 		return KEEP_WATCHING;
 	}
 	if (peer->state != CHANNELD_NORMAL || !peer->owner) {
+		log_debug(peer->ld->log,
+			  "Funding tx announce ready, but peer state %s %s",
+			  peer_state_name(peer->state),
+			  peer->owner ? peer->owner->name : "unowned");
 		return KEEP_WATCHING;
 	}
 	subd_send_msg(peer->owner,

tests/test_lightningd.py

@@ -183,7 +183,7 @@ def fund_channel(self,l1,l2,amount):
         # Technically, this is async to fundchannel.
         l1.daemon.wait_for_log('sendrawtx exit 0')
 
-        l1.bitcoin.rpc.generate(6)
+        l1.bitcoin.rpc.generate(1)
 
         l1.daemon.wait_for_log('-> CHANNELD_NORMAL')
         l2.daemon.wait_for_log('-> CHANNELD_NORMAL')
@@ -307,6 +307,10 @@ def test_gossip_jsonrpc(self):
 
         self.fund_channel(l1,l2,10**5)
 
+        # Shouldn't send announce signatures until 6 deep.
+        assert not l1.daemon.is_in_log('peer_out WIRE_ANNOUNCEMENT_SIGNATURES')
+
+        l1.bitcoin.rpc.generate(5)
         l1.daemon.wait_for_log('peer_out WIRE_ANNOUNCEMENT_SIGNATURES')
         l1.daemon.wait_for_log('peer_in WIRE_ANNOUNCEMENT_SIGNATURES')
 
@@ -366,6 +370,9 @@ def test_routing_gossip(self):
             src.rpc.connect('localhost', dst.info['port'], dst.info['id'])
             src.openchannel(dst, 20000)
 
+        # Allow announce messages.
+        l1.bitcoin.rpc.generate(5)
+
         def settle_gossip(n):
             """Wait for gossip to settle at the node
             """
@@ -407,6 +414,9 @@ def test_forward(self):
         self.fund_channel(l1, l2, 10**6)
         self.fund_channel(l2, l3, 10**6)
 
+        # Allow announce messages.
+        l1.bitcoin.rpc.generate(5)
+        
         # If they're at different block heights we can get spurious errors.
         sync_blockheight(l1, l2, l3)