connectd: Expand debug message for ping

This should help debug failed ping responses showing up in CI.

Author: ddustin

common/ping.c

@@ -9,8 +9,12 @@ bool check_ping_make_pong(const tal_t *ctx, const u8 *ping, u8 **pong)
 	u16 num_pong_bytes;
 	u8 *ignored;
 
-	if (!fromwire_ping(ctx, ping, &num_pong_bytes, &ignored))
+	status_debug("Making a pong!");
+
+	if (!fromwire_ping(ctx, ping, &num_pong_bytes, &ignored)) {
+		status_debug("Failed to make pong -- ping was invalid");
 		return false;
+	}
 	tal_free(ignored);
 
 	/* BOLT #1:
@@ -33,8 +37,11 @@ bool check_ping_make_pong(const tal_t *ctx, const u8 *ping, u8 **pong)
 		ignored = tal_arrz(ctx, u8, num_pong_bytes);
 		*pong = towire_pong(ctx, ignored);
 		tal_free(ignored);
-	} else
+	} else {
+		status_debug("Failed to make pong -- num_pong_bytes was"
+			     " too large!");
 		*pong = NULL;
+	}
 
 	return true;
 }
@@ -50,6 +57,8 @@ u8 *make_ping(const tal_t *ctx, u16 num_pong_bytes, u16 padlen)
 	 */
 	u8 *ping, *ignored = tal_arrz(ctx, u8, padlen);
 
+	status_debug("Making a ping!");
+
 	ping = towire_ping(ctx, num_pong_bytes, ignored);
 	tal_free(ignored);
 	return ping;

connectd/connectd.c

@@ -149,6 +149,7 @@ static struct peer *new_peer(struct daemon *daemon,
 	peer->draining = false;
 	peer->peer_outq = msg_queue_new(peer, false);
 	peer->last_recv_time = time_now();
+	peer->ping_timer = NULL;
 	peer->is_websocket = is_websocket;
 	peer->dev_writes_enabled = NULL;
 	peer->dev_read_enabled = true;

connectd/multiplex.c

@@ -440,6 +440,9 @@ static struct io_plan *encrypt_and_send(struct peer *peer,
 
 	set_urgent_flag(peer, is_urgent(type));
 
+	status_peer_debug(&peer->id, "encrypt_and_send -> io_write %s",
+			  peer_wire_name(type));
+
 	/* We free this and the encrypted version in next write_to_peer */
 	peer->sent_to_peer = cryptomsg_encrypt_msg(peer, &peer->cs, msg);
 	return io_write(peer->to_peer,
@@ -562,29 +565,46 @@ static void set_ping_timer(struct peer *peer)
 		peer->ping_timer = NULL;
 		return;
 	}
+	status_peer_debug(&peer->id, "set_ping_timer, peer->ping_timer = %p",
+			  peer->ping_timer);
 	peer->ping_timer = new_reltimer(&peer->daemon->timers, peer,
 					time_from_sec(15 + pseudorand(30)),
 					send_ping, peer);
 }
 
 static void send_ping(struct peer *peer)
 {
+	struct timeabs tnow = time_now();
 	/* If it's still sending us traffic, maybe ping reply is backed up?
 	 * That's OK, ping is just to make sure it's still alive, and clearly
 	 * it is. */
 	if (time_before(peer->last_recv_time,
-			timeabs_sub(time_now(), time_from_sec(60)))) {
+			timeabs_sub(tnow, time_from_sec(60)))) {
 		/* Already have a ping in flight? */
 		if (peer->expecting_pong != PONG_UNEXPECTED) {
-			status_peer_debug(&peer->id, "Last ping unreturned: hanging up");
+			status_peer_debug(&peer->id, "Last ping unreturned:"
+					  " hanging up, expecting_pong: %d,"
+					  " last_recv_time: %lu seconds,"
+					  " tnow: %lu seconds,"
+					  " tnow - 60: %lu seconds,"
+					  " tnow - last_recv_time: %lu seconds",
+					  peer->expecting_pong,
+					  (long)peer->last_recv_time.ts.tv_sec,
+					  (long)tnow.ts.tv_sec,
+					  (long)timeabs_sub(tnow, time_from_sec(60)).ts.tv_sec,
+					  (long)tnow.ts.tv_sec - (long)peer->last_recv_time.ts.tv_sec);
 			if (peer->to_peer)
 				io_close(peer->to_peer);
 			return;
 		}
 
+		status_peer_debug(&peer->id, "Sending a ping");
 		inject_peer_msg(peer, take(make_ping(NULL, 1, 0)));
 		peer->expecting_pong = PONG_EXPECTED_PROBING;
 	}
+	else {
+		status_peer_debug(&peer->id, "send_ping (skip) not been 60s yet");
+	}
 
 	set_ping_timer(peer);
 }
@@ -617,20 +637,29 @@ static void handle_ping_in(struct peer *peer, const u8 *msg)
 {
 	u8 *pong;
 
+	status_peer_debug(&peer->id, "Ping recevied!");
+
 	if (!check_ping_make_pong(NULL, msg, &pong)) {
 		send_warning(peer, "Invalid ping %s", tal_hex(msg, msg));
 		return;
 	}
 
-	if (pong)
+	if (pong) {
+		status_peer_debug(&peer->id, "Sending a pong!");
 		inject_peer_msg(peer, take(pong));
+	}
+	else {
+		status_peer_debug(&peer->id, "We're NOT sending a pong.. why?");
+	}
 }
 
 static void handle_ping_reply(struct peer *peer, const u8 *msg)
 {
 	u8 *ignored;
 	size_t i;
 
+	status_peer_debug(&peer->id, "Receiving a pong!");
+
 	/* We print this out because we asked for pong, so can't spam us... */
 	if (!fromwire_pong(msg, msg, &ignored))
 		status_peer_unusual(&peer->id, "Got malformed ping reply %s",
@@ -656,6 +685,8 @@ static void handle_pong_in(struct peer *peer, const u8 *msg)
 		handle_ping_reply(peer, msg);
 		/* fall thru */
 	case PONG_EXPECTED_PROBING:
+		// TODO: set peer->last_recv_time to time_now() ?
+		status_peer_debug(&peer->id, "Received and ignored a pong! (probing)");
 		peer->expecting_pong = PONG_UNEXPECTED;
 		return;
 	case PONG_UNEXPECTED:
@@ -1171,6 +1202,8 @@ static struct io_plan *read_body_from_peer_done(struct io_conn *peer_conn,
        /* We got something! */
        peer->last_recv_time = time_now();
 
+       status_peer_debug(&peer->id, "Setting last_recv_time to now!");
+
        /* Don't process packets while we're closing */
        if (peer->draining)
 	       return next_read(peer_conn, peer);
@@ -1386,6 +1419,8 @@ void send_manual_ping(struct daemon *daemon, const u8 *msg)
 	u16 len, num_pong_bytes;
 	struct peer *peer;
 
+	status_debug("Sending a ping manually");
+
 	if (!fromwire_connectd_ping(msg, &id, &num_pong_bytes, &len))
 		master_badmsg(WIRE_CONNECTD_PING, msg);
 
@@ -1435,6 +1470,6 @@ void send_manual_ping(struct daemon *daemon, const u8 *msg)
 	peer->expecting_pong = PONG_EXPECTED_COMMAND;
 
 	/* Since we're doing this manually, kill and restart timer. */
-	tal_free(peer->ping_timer);
+	peer->ping_timer = tal_free(peer->ping_timer);
 	set_ping_timer(peer);
 }