connectd: at disconnected, tell lightningd how long we were connected.

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

connectd/connectd.c

@@ -112,6 +112,7 @@ static struct peer *new_peer(struct daemon *daemon,
 			     const struct crypto_state *cs,
 			     const u8 *their_features,
 			     enum is_websocket is_websocket,
+			     struct timemono connect_starttime,
 			     struct io_conn *conn STEALS,
 			     int *fd_for_subd)
 {
@@ -119,6 +120,7 @@ static struct peer *new_peer(struct daemon *daemon,
 
 	peer->daemon = daemon;
 	peer->id = *id;
+	peer->connect_starttime = connect_starttime;
 	peer->counter = daemon->connection_counter++;
 	peer->cs = *cs;
 	peer->subds = tal_arr(peer, struct subd *, 0);
@@ -258,11 +260,12 @@ static void reset_reconnect_timer(struct peer *peer)
 
 void send_disconnected(struct daemon *daemon,
 		       const struct node_id *id,
-		       u64 connectd_counter)
+		       u64 connectd_counter,
+		       struct timemono starttime)
 {
 	/* lightningd: it's gone */
 	daemon_conn_send(daemon->master,
-			 take(towire_connectd_peer_disconnected(NULL, id, connectd_counter)));
+			 take(towire_connectd_peer_disconnected(NULL, id, connectd_counter, time_to_nsec(timemono_since(starttime)))));
 
 	/* Tell gossipd to stop asking this peer gossip queries */
 	daemon_conn_send(daemon->gossipd,
@@ -282,6 +285,7 @@ struct io_plan *peer_connected(struct io_conn *conn,
 			       struct crypto_state *cs,
 			       const u8 *their_features TAKES,
 			       enum is_websocket is_websocket,
+			       struct timemono starttime,
 			       bool incoming)
 {
 	u8 *msg;
@@ -294,11 +298,13 @@ struct io_plan *peer_connected(struct io_conn *conn,
 	const char *connect_reason;
 	u64 connect_time_nsec;
 	u64 prev_connectd_counter;
+	struct timemono prev_connect_start;
 
 	/* We remove any previous connection immediately, on the assumption it's dead */
 	oldpeer = peer_htable_get(daemon->peers, id);
 	if (oldpeer) {
 		prev_connectd_counter = oldpeer->counter;
+		prev_connect_start = oldpeer->connect_starttime;
 		destroy_peer_immediately(oldpeer);
 	}
 
@@ -320,7 +326,8 @@ struct io_plan *peer_connected(struct io_conn *conn,
 	if (unsup != -1) {
 		/* We were going to send a reconnect message, but not now! */
 		if (oldpeer)
-			send_disconnected(daemon, id, prev_connectd_counter);
+			send_disconnected(daemon, id, prev_connectd_counter,
+					  prev_connect_start);
 		status_peer_unusual(id, "Unsupported feature %u", unsup);
 		msg = towire_warningfmt(NULL, NULL, "Unsupported feature %u",
 					unsup);
@@ -331,7 +338,8 @@ struct io_plan *peer_connected(struct io_conn *conn,
 	if (!feature_check_depends(their_features, &depender, &missing)) {
 		/* We were going to send a reconnect message, but not now! */
 		if (oldpeer)
-			send_disconnected(daemon, id, prev_connectd_counter);
+			send_disconnected(daemon, id, prev_connectd_counter,
+					  prev_connect_start);
 		status_peer_unusual(id, "Feature %zu requires feature %zu",
 				    depender, missing);
 		msg = towire_warningfmt(NULL, NULL,
@@ -374,13 +382,14 @@ struct io_plan *peer_connected(struct io_conn *conn,
 	}
 
 	/* This contains the per-peer state info; gossipd fills in pps->gs */
-	peer = new_peer(daemon, id, cs, their_features, is_websocket, conn,
+	peer = new_peer(daemon, id, cs, their_features, is_websocket, starttime, conn,
 			&subd_fd);
 	/* Only takes over conn if it succeeds. */
 	if (!peer) {
 		/* We were going to send a reconnect message, but not now! */
 		if (oldpeer)
-			send_disconnected(daemon, id, prev_connectd_counter);
+			send_disconnected(daemon, id, prev_connectd_counter,
+					  prev_connect_start);
 		return io_close(conn);
 	}
 
@@ -398,7 +407,8 @@ struct io_plan *peer_connected(struct io_conn *conn,
 						       prev_connectd_counter,
 						       peer->counter,
 						       addr, remote_addr,
-						       incoming, their_features);
+						       incoming, their_features,
+						       time_to_nsec(timemono_since(prev_connect_start)));
 	} else {
 		/* Tell gossipd about new peer */
 		msg = towire_gossipd_new_peer(NULL, id, option_gossip_queries);
@@ -438,13 +448,15 @@ static struct io_plan *handshake_in_success(struct io_conn *conn,
 					    struct crypto_state *cs,
 					    struct oneshot *timeout,
 					    enum is_websocket is_websocket,
+					    struct timemono starttime,
 					    struct daemon *daemon)
 {
 	struct node_id id;
 	node_id_from_pubkey(&id, id_key);
 	status_peer_debug(&id, "Connect IN");
 	return peer_exchange_initmsg(conn, daemon, daemon->our_features,
-				     cs, &id, addr, timeout, is_websocket, true);
+				     cs, &id, addr, timeout, is_websocket,
+				     starttime, true);
 }
 
 /*~ If the timer goes off, we simply free everything, which hangs up. */
@@ -730,6 +742,7 @@ static struct io_plan *handshake_out_success(struct io_conn *conn,
 					     struct crypto_state *cs,
 					     struct oneshot *timeout,
 					     enum is_websocket is_websocket,
+					     struct timemono starttime,
 					     struct connecting *connect)
 {
 	struct node_id id;
@@ -739,7 +752,8 @@ static struct io_plan *handshake_out_success(struct io_conn *conn,
 	status_peer_debug(&id, "Connect OUT");
 	return peer_exchange_initmsg(conn, connect->daemon,
 				     connect->daemon->our_features,
-				     cs, &id, addr, timeout, is_websocket, false);
+				     cs, &id, addr, timeout, is_websocket,
+				     starttime, false);
 }
 
 struct io_plan *connection_out(struct io_conn *conn, struct connecting *connect)

connectd/connectd.h

@@ -64,6 +64,8 @@ struct peer {
 	struct node_id id;
 	/* Counters and keys for symmetric crypto */
 	struct crypto_state cs;
+	/* Time when we first connected */
+	struct timemono connect_starttime;
 
 	/* Connection to the peer (NULL if it's disconnected and we're flushing) */
 	struct io_conn *to_peer;
@@ -388,12 +390,14 @@ struct io_plan *peer_connected(struct io_conn *conn,
 			       struct crypto_state *cs,
 			       const u8 *their_features TAKES,
 			       enum is_websocket is_websocket,
+			       struct timemono starttime,
 			       bool incoming);
 
 /* Tell gossipd and lightningd that this peer is gone. */
 void send_disconnected(struct daemon *daemon,
 		       const struct node_id *id,
-		       u64 connectd_counter);
+		       u64 connectd_counter,
+		       struct timemono starttime);
 
 /* Free peer immediately (don't wait for draining). */
 void destroy_peer_immediately(struct peer *peer);

connectd/connectd_wire.csv

@@ -90,6 +90,7 @@ msgdata,connectd_peer_connected,connect_nsec,u64,
 msgtype,connectd_peer_disconnected,2006
 msgdata,connectd_peer_disconnected,id,node_id,
 msgdata,connectd_peer_disconnected,counter,u64,
+msgdata,connectd_peer_disconnected,connected_time_nsec,u64,
 
 # Connectd -> master: peer reconnected (disconnect & connect)
 msgtype,connectd_peer_reconnected,2010
@@ -101,6 +102,7 @@ msgdata,connectd_peer_reconnected,remote_addr,?wireaddr,
 msgdata,connectd_peer_reconnected,incoming,bool,
 msgdata,connectd_peer_reconnected,flen,u16,
 msgdata,connectd_peer_reconnected,features,u8,flen
+msgdata,connectd_peer_reconnected,connected_time_nsec,u64,
 
 # Master -> connectd: make peer active immediately (we want to talk) (+ fd to subd).
 msgtype,connectd_peer_connect_subd,2004

connectd/handshake.c

@@ -5,6 +5,7 @@
 #include <ccan/endian/endian.h>
 #include <ccan/io/io.h>
 #include <ccan/mem/mem.h>
+#include <ccan/time/time.h>
 #include <common/crypto_state.h>
 #include <common/ecdh.h>
 #include <common/status.h>
@@ -178,6 +179,9 @@ struct handshake {
 	/* Are we connected via a websocket? */
 	enum is_websocket is_websocket;
 
+	/* Time they first connected */
+	struct timemono starttime;
+
 	/* Function to call once handshake complete. */
 	struct io_plan *(*cb)(struct io_conn *conn,
 			      const struct pubkey *their_id,
@@ -185,6 +189,7 @@ struct handshake {
 			      struct crypto_state *cs,
 			      struct oneshot *timeout,
 			      enum is_websocket is_websocket,
+			      struct timemono starttime,
 			      void *cbarg);
 	void *cbarg;
 };
@@ -357,12 +362,14 @@ static struct io_plan *handshake_succeeded(struct io_conn *conn,
 			      struct crypto_state *cs,
 			      struct oneshot *timeout,
 			      enum is_websocket is_websocket,
+			      struct timemono starttime,
 			      void *cbarg);
 	void *cbarg;
 	struct pubkey their_id;
 	struct wireaddr_internal addr;
 	struct oneshot *timeout;
 	enum is_websocket is_websocket;
+	struct timemono starttime;
 
 	/* BOLT #8:
 	 *
@@ -396,9 +403,10 @@ static struct io_plan *handshake_succeeded(struct io_conn *conn,
 	addr = h->addr;
 	timeout = h->timeout;
 	is_websocket = h->is_websocket;
+	starttime = h->starttime;
 
 	tal_free(h);
-	return cb(conn, &their_id, &addr, &cs, timeout, is_websocket, cbarg);
+	return cb(conn, &their_id, &addr, &cs, timeout, is_websocket, starttime, cbarg);
 }
 
 static struct handshake *new_handshake(const tal_t *ctx,
@@ -983,12 +991,14 @@ struct io_plan *responder_handshake_(struct io_conn *conn,
 							   struct crypto_state *,
 							   struct oneshot *,
 							   enum is_websocket,
+							   struct timemono,
 							   void *cbarg),
 				     void *cbarg)
 {
 	struct handshake *h = new_handshake(conn, my_id);
 
 	h->side = RESPONDER;
+	h->starttime = time_mono();
 	h->my_id = *my_id;
 	h->addr = *addr;
 	h->cbarg = cbarg;
@@ -1011,12 +1021,14 @@ struct io_plan *initiator_handshake_(struct io_conn *conn,
 							   struct crypto_state *,
 							   struct oneshot *timeout,
 							   enum is_websocket is_websocket,
+							   struct timemono,
 							   void *cbarg),
 				     void *cbarg)
 {
 	struct handshake *h = new_handshake(conn, their_id);
 
 	h->side = INITIATOR;
+	h->starttime = time_mono();
 	h->my_id = *my_id;
 	h->their_id = *their_id;
 	h->addr = *addr;

connectd/handshake.h

@@ -26,7 +26,8 @@ enum is_websocket {
 						 const struct wireaddr_internal *, \
 						 struct crypto_state *, \
 						 struct oneshot *,	\
-						 enum is_websocket),	\
+						 enum is_websocket,	\
+						 struct timemono),	\
 			     (cbarg))
 
 
@@ -42,6 +43,7 @@ struct io_plan *initiator_handshake_(struct io_conn *conn,
 							   struct crypto_state *,
 							   struct oneshot *timeout,
 							   enum is_websocket,
+							   struct timemono,
 							   void *cbarg),
 				     void *cbarg);
 
@@ -55,7 +57,8 @@ struct io_plan *initiator_handshake_(struct io_conn *conn,
 						 const struct wireaddr_internal *, \
 						 struct crypto_state *, \
 						 struct oneshot *,	\
-						 enum is_websocket),	\
+						 enum is_websocket,	\
+						 struct timemono),	\
 			     (cbarg))
 
 struct io_plan *responder_handshake_(struct io_conn *conn,
@@ -69,6 +72,7 @@ struct io_plan *responder_handshake_(struct io_conn *conn,
 							   struct crypto_state *,
 							   struct oneshot *,
 							   enum is_websocket,
+							   struct timemono,
 							   void *cbarg),
 				     void *cbarg);
 #endif /* LIGHTNING_CONNECTD_HANDSHAKE_H */

connectd/multiplex.c

@@ -1392,9 +1392,10 @@ static void destroy_peer_conn(struct io_conn *peer_conn, struct peer *peer)
 {
 	assert(peer->to_peer == peer_conn);
 
-	/* We are no longer connected.  Tell lightningd & gossipd*/
+	/* We are no longer connected.  Tell lightningd & gossipd */
 	peer->to_peer = NULL;
-	send_disconnected(peer->daemon, &peer->id, peer->counter);
+	send_disconnected(peer->daemon, &peer->id, peer->counter,
+			  peer->connect_starttime);
 
 	/* Wake subds: give them 5 seconds to flush. */
 	for (size_t i = 0; i < tal_count(peer->subds); i++) {

connectd/peer_exchange_initmsg.c

@@ -34,6 +34,9 @@ struct early_peer {
 
 	/* Timeout in case it takes too long */
 	struct oneshot *timeout;
+
+	/* We record time when we first accepted socket */
+	struct timemono starttime;
 };
 
 static bool contains_common_chain(struct bitcoin_blkid *chains)
@@ -152,6 +155,7 @@ static struct io_plan *peer_init_received(struct io_conn *conn,
 			      &peer->cs,
 			      take(features),
 			      peer->is_websocket,
+			      peer->starttime,
 			      peer->incoming);
 }
 
@@ -206,6 +210,7 @@ struct io_plan *peer_exchange_initmsg(struct io_conn *conn,
 				      const struct wireaddr_internal *addr,
 				      struct oneshot *timeout,
 				      enum is_websocket is_websocket,
+				      struct timemono starttime,
 				      bool incoming)
 {
 	/* If conn is closed, forget peer */
@@ -220,6 +225,7 @@ struct io_plan *peer_exchange_initmsg(struct io_conn *conn,
 	peer->incoming = incoming;
 	peer->is_websocket = is_websocket;
 	peer->timeout = timeout;
+	peer->starttime = starttime;
 
 	/* BOLT #1:
 	 *

connectd/peer_exchange_initmsg.h

@@ -19,6 +19,7 @@ struct io_plan *peer_exchange_initmsg(struct io_conn *conn,
 				      const struct wireaddr_internal *addr,
 				      struct oneshot *timeout,
 				      enum is_websocket is_websocket,
+				      struct timemono starttime,
 				      bool incoming);
 
 #endif /* LIGHTNING_CONNECTD_PEER_EXCHANGE_INITMSG_H */

connectd/test/run-initiator-success.c

@@ -186,6 +186,7 @@ static struct io_plan *success(struct io_conn *conn UNUSED,
 			       struct crypto_state *cs,
 			       struct oneshot *timeout UNUSED,
 			       enum is_websocket is_websocket UNUSED,
+			       struct timemono starttime UNUSED,
 			       void *unused UNUSED)
 {
 	assert(pubkey_eq(them, &rs_pub));

connectd/test/run-responder-success.c

@@ -185,6 +185,7 @@ static struct io_plan *success(struct io_conn *conn UNUSED,
 			       struct crypto_state *cs,
 			       struct oneshot *timeout UNUSED,
 			       enum is_websocket is_websocket UNUSED,
+			       struct timemono starttime UNUSED,
 			       void *unused UNUSED)
 {
 	assert(secret_eq_str(&cs->sk, expect_sk));