Latency reporting

Makefile.am

@@ -25,6 +25,10 @@ if IS_DEVENV
 CFLAGS += -DDEVENV
 endif
 
+if IS_LATENCY
+CFLAGS += -DENABLE_LATENCY
+endif
+
 if IS_LINUX
 CFLAGS += -rdynamic # for stack traces
 endif
@@ -185,6 +189,7 @@ dist_tmate_slave_SOURCES = \
 	tmate-ssh-client-pty.c \
 	tmate-ssh-daemon.c \
 	tmate-ssh-exec.c \
+	tmate-ssh-latency.c \
 	tmate-ssh-server.c \
 	tmux.c \
 	tty-acs.c \

client.c

@@ -64,6 +64,9 @@ void		client_dispatch(struct imsg *, void *);
 void		client_dispatch_attached(struct imsg *);
 void		client_dispatch_wait(struct imsg *, const char *);
 const char     *client_exit_message(void);
+#ifdef TMATE_SLAVE
+void client_report_latency(int latency_ms);
+#endif
 
 /*
  * Get server create lock. If already held then server start is happening in
@@ -728,3 +731,10 @@ client_dispatch_attached(struct imsg *imsg)
 		break;
 	}
 }
+
+#ifdef TMATE_SLAVE
+void client_report_latency(int latency_ms)
+{
+	proc_send(client_peer, MSG_LATENCY, -1, &latency_ms, sizeof(latency_ms));
+}
+#endif

configure.ac

@@ -23,6 +23,13 @@ PKG_PROG_PKG_CONFIG
 # Default tmux.conf goes in /etc not ${prefix}/etc.
 test "$sysconfdir" = '${prefix}/etc' && sysconfdir=/etc
 
+AC_ARG_ENABLE(
+	latency,
+	AC_HELP_STRING(--enable-latency, "enable latency (requires libssh head)"),
+	found_latency=$enable_latency
+)
+AM_CONDITIONAL(IS_LATENCY, test "x$found_latency" = xyes)
+
 AC_ARG_ENABLE(
 	devenv,
 	AC_HELP_STRING(--enable-devenv, "dev env (port 2200, no random tokens)"),

server-client.c

@@ -1111,6 +1111,17 @@ server_client_dispatch(struct imsg *imsg, void *arg)
 
 		server_client_dispatch_shell(c);
 		break;
+#ifdef TMATE_SLAVE
+	case MSG_LATENCY:
+		{
+		int latency_ms;
+		if (datalen != sizeof(latency_ms))
+			fatalx("bad MSG_LATENCY size");
+		memcpy(&latency_ms, data, sizeof(latency_ms));
+		tmate_notify_latency(tmate_session, c, latency_ms);
+		}
+		break;
+#endif
 	}
 }
 

tmate-protocol.h

@@ -11,6 +11,7 @@ enum tmate_control_out_msg_types {
 	TMATE_CTL_CLIENT_JOIN,
 	TMATE_CTL_CLIENT_LEFT,
 	TMATE_CTL_EXEC,
+	TMATE_CTL_LATENCY,
 };
 
 /*
@@ -23,6 +24,7 @@ enum tmate_control_out_msg_types {
 [TMATE_CTL_CLIENT_JOIN, int: client_id, string: ip_address, string: pubkey, boolean: readonly]
 [TMATE_CTL_CLIENT_LEFT, int: client_id]
 [TMATE_CTL_EXEC, string: username, string: ip_address, string: pubkey, string: command]
+[TMATE_CTL_LATENCY, int: client_id, int: latency_ms] // client_id == -1: tmate host
 */
 
 enum tmate_control_in_msg_types {

tmate-proxy.c

@@ -224,6 +224,23 @@ void tmate_notify_client_left(__unused struct tmate_session *session,
 	pack(int, c->id);
 }
 
+void tmate_notify_latency(__unused struct tmate_session *session,
+			  struct client *c, int latency_ms)
+{
+	int cid;
+
+	if (!tmate_has_proxy())
+		return;
+
+	cid = c ? c->id : -1;
+	tmate_debug("Client latency (cid=%d): %dms", cid, latency_ms);
+
+	pack(array, 3);
+	pack(int, TMATE_CTL_LATENCY);
+	pack(int, cid);
+	pack(int, latency_ms);
+}
+
 void tmate_send_proxy_daemon_msg(__unused struct tmate_session *session,
 				 struct tmate_unpacker *uk)
 {

tmate-ssh-client-pty.c

@@ -5,6 +5,12 @@
 #include "tmate.h"
 
 extern void client_signal(int sig);
+extern void client_report_latency(int latency_ms);
+
+static void on_latency_callback(__unused void *userdata, int latency_ms)
+{
+	client_report_latency(latency_ms);
+}
 
 static int on_ssh_channel_read(__unused ssh_session _session,
 			       __unused ssh_channel channel,
@@ -110,4 +116,6 @@ void tmate_client_pty_init(struct tmate_session *session)
 	event_set(&session->ev_pty, session->pty,
 		  EV_READ | EV_PERSIST, __on_pty_event, session);
 	event_add(&session->ev_pty, NULL);
+
+	tmate_add_ssh_latency_callback(client, on_latency_callback, session);
 }

tmate-ssh-daemon.c

@@ -1,6 +1,12 @@
 #include "tmate.h"
 #include <errno.h>
 
+static void on_latency_callback(void *userdata, int latency_ms)
+{
+	struct tmate_session *session = userdata;
+	tmate_notify_latency(session, NULL, latency_ms);
+}
+
 static void on_daemon_decoder_read(void *userdata, struct tmate_unpacker *uk)
 {
 	struct tmate_session *session = userdata;
@@ -80,4 +86,6 @@ void tmate_daemon_init(struct tmate_session *session)
 	tmate_decoder_init(&session->daemon_decoder, on_daemon_decoder_read, session);
 
 	tmate_init_proxy(session, NULL);
+
+	tmate_add_ssh_latency_callback(client, on_latency_callback, session);
 }

tmate-ssh-latency.c

@@ -0,0 +1,146 @@
+#include <libssh/libssh.h>
+#include <libssh/server.h>
+#include <libssh/callbacks.h>
+#include <sys/socket.h>
+#include <netinet/tcp.h>
+#include <sys/wait.h>
+#include <stdio.h>
+#include <event.h>
+#include <arpa/inet.h>
+#include <time.h>
+
+#include "tmate.h"
+
+static void on_keepalive_timer(evutil_socket_t fd, short what, void *arg);
+
+static void start_keepalive_timer(struct tmate_ssh_client *client,
+				  int timeout_ms)
+{
+	struct timeval tv;
+	tv.tv_sec = timeout_ms / 1000;
+	tv.tv_usec = (timeout_ms % 1000)*1000;
+
+	evtimer_set(&client->ev_keepalive_timer, on_keepalive_timer, client);
+	evtimer_add(&client->ev_keepalive_timer, &tv);
+}
+
+static void on_keepalive_timer(__unused evutil_socket_t fd,
+			       __unused short what, void *arg)
+{
+	struct tmate_ssh_client *client = arg;
+
+	if (ssh_send_keepalive(client->session) == SSH_ERROR)
+		return;
+
+#ifdef ENABLE_LATENCY
+	if (client->keepalive_sent_at.tv_sec == 0) {
+		if (clock_gettime(CLOCK_MONOTONIC, &client->keepalive_sent_at) < 0)
+		    tmate_fatal("cannot clock_gettime()");
+	}
+#endif
+
+	/*
+	 * We restart the timer here as opposed to the ssh_pong callback,
+	 * because some clients may be broken and our callback may not be
+	 * called, and we must ensure that we send keepalives periodically
+	 * because some connections may get closed for inactivity due to the
+	 * presence of hostile routers.
+	 */
+	start_keepalive_timer(client, client->keepalive_interval_ms);
+}
+
+
+#ifdef ENABLE_LATENCY
+static void timespec_subtract(struct timespec *result,
+			      struct timespec *x, struct timespec *y);
+
+static unsigned long long timespec_to_millisec(struct timespec *ts);
+
+static void ssh_pong(struct tmate_ssh_client *client)
+{
+	struct timespec now, tmp;
+	int latency_ms;
+
+	if (!client->latency_cb)
+		return;
+
+	if (!client->keepalive_sent_at.tv_sec)
+		return;
+
+	if (clock_gettime(CLOCK_MONOTONIC, &now) < 0)
+		tmate_fatal("cannot clock_gettime()");
+
+	timespec_subtract(&tmp, &now, &client->keepalive_sent_at);
+	latency_ms = timespec_to_millisec(&tmp);
+	client->latency_cb(client->latency_cb_userdata, latency_ms);
+
+	client->keepalive_sent_at.tv_sec = 0;
+}
+
+static void ssh_request_denied_callback(__unused ssh_session session, void *userdata)
+{
+	ssh_pong(userdata);
+}
+
+static void ssh_unimplemented_packet_callback(__unused ssh_session session,
+					      __unused uint32_t seq, void *userdata)
+{
+	ssh_pong(userdata);
+}
+
+void tmate_start_ssh_latency_probes(struct tmate_ssh_client *client,
+				    struct ssh_server_callbacks_struct *server_callbacks,
+				    int keepalive_interval_ms)
+{
+	client->keepalive_interval_ms = keepalive_interval_ms;
+	client->latency_cb = NULL;
+	server_callbacks->client_unimplemented_packet_function = ssh_unimplemented_packet_callback;
+	server_callbacks->client_request_denied_function = ssh_request_denied_callback;
+	client->keepalive_sent_at.tv_sec = 0;
+	start_keepalive_timer(client, 3000);
+}
+
+void tmate_add_ssh_latency_callback(struct tmate_ssh_client *client,
+				    ssh_client_latency_cb cb, void *userdata)
+{
+	if (client->latency_cb)
+		tmate_fatal("only one latency callback for now");
+
+	client->latency_cb = cb;
+	client->latency_cb_userdata = userdata;
+}
+
+static void timespec_subtract(struct timespec *result,
+			      struct timespec *x, struct timespec *y)
+{
+	if (x->tv_nsec < y->tv_nsec) {
+		result->tv_sec = x->tv_sec - y->tv_sec - 1;
+		result->tv_nsec = x->tv_nsec - y->tv_nsec + 1000000000;
+	} else {
+		result->tv_sec = x->tv_sec - y->tv_sec;
+		result->tv_nsec = x->tv_nsec - y->tv_nsec;
+	}
+}
+
+static unsigned long long timespec_to_millisec(struct timespec *ts)
+{
+	return ts->tv_sec * 1000ULL + ts->tv_nsec / 1000000ULL;
+}
+
+#else
+
+void tmate_start_ssh_latency_probes(struct tmate_ssh_client *client,
+				    __unused struct ssh_server_callbacks_struct *server_callbacks,
+				    int keepalive_interval_ms)
+{
+	client->keepalive_interval_ms = keepalive_interval_ms;
+	start_keepalive_timer(client, 3000);
+}
+
+void tmate_add_ssh_latency_callback(__unused struct tmate_ssh_client *client,
+				    __unused ssh_client_latency_cb cb, __unused void *userdata)
+{
+}
+
+
+#endif

tmate-ssh-server.c

@@ -10,25 +10,6 @@
 
 #include "tmate.h"
 
-static void start_keepalive_timer(struct tmate_ssh_client *client);
-static void on_keepalive_timer(__unused evutil_socket_t fd,
-			       __unused short what, void *arg)
-{
-	struct tmate_ssh_client *client = arg;
-
-	ssh_send_keepalive(client->session);
-	start_keepalive_timer(client);
-}
-
-static void start_keepalive_timer(struct tmate_ssh_client *client)
-{
-	struct timeval tv = { TMATE_SSH_KEEPALIVE, 0 };
-
-	evtimer_set(&client->ev_keepalive_timer,
-		    on_keepalive_timer, client);
-	evtimer_add(&client->ev_keepalive_timer, &tv);
-}
-
 static int pty_request(__unused ssh_session session,
 		       __unused ssh_channel channel,
 		       __unused const char *term,
@@ -233,7 +214,8 @@ static void client_bootstrap(struct tmate_session *_session)
 
 	alarm(0);
 
-	start_keepalive_timer(client);
+	/* The latency is callback set later */
+	tmate_start_ssh_latency_probes(client, &ssh_server_cb, TMATE_SSH_KEEPALIVE * 1000);
 	register_on_ssh_read(client);
 
 	tmate_spawn_slave(_session);

tmate.h

@@ -7,6 +7,7 @@
 #include <libssh/libssh.h>
 #include <libssh/callbacks.h>
 #include <event.h>
+#include <time.h>
 
 #include "tmux.h"
 struct tmate_session;
@@ -133,12 +134,20 @@ extern void tmate_flush_pty(struct tmate_session *session);
 /* tmate-ssh-server.c */
 
 #define TMATE_SSH_BANNER "tmate"
-#define TMATE_SSH_KEEPALIVE 60
+#define TMATE_SSH_KEEPALIVE 30
 
 #define TMATE_ROLE_DAEMON	1
 #define TMATE_ROLE_PTY_CLIENT	2
 #define TMATE_ROLE_EXEC		3
 
+struct tmate_ssh_client;
+typedef void ssh_client_latency_cb(void *userdata, int latency_ms);
+extern void tmate_start_ssh_latency_probes(struct tmate_ssh_client *client,
+					   struct ssh_server_callbacks_struct *server_callbacks,
+					   int keepalive_interval_ms);
+extern void tmate_add_ssh_latency_callback(struct tmate_ssh_client *client,
+					   ssh_client_latency_cb cb, void *userdata);
+
 struct tmate_ssh_client {
 	char ip_address[64];
 
@@ -160,7 +169,14 @@ struct tmate_ssh_client {
 	struct winsize winsize_pty;
 
 	struct event ev_ssh;
+
 	struct event ev_keepalive_timer;
+	int keepalive_interval_ms;
+#ifdef ENABLE_LATENCY
+	ssh_client_latency_cb *latency_cb;
+	void *latency_cb_userdata;
+	struct timespec keepalive_sent_at;
+#endif
 };
 
 extern void tmate_ssh_server_main(struct tmate_session *session,
@@ -241,6 +257,7 @@ extern void tmate_spawn_slave(struct tmate_session *session);
 extern void tmate_proxy_exec(struct tmate_session *session, const char *command);
 extern void tmate_notify_client_join(struct tmate_session *s, struct client *c);
 extern void tmate_notify_client_left(struct tmate_session *s, struct client *c);
+extern void tmate_notify_latency(struct tmate_session *session, struct client *c, int latency_ms);
 
 extern void tmate_send_proxy_daemon_msg(struct tmate_session *session,
 					 struct tmate_unpacker *uk);

tmux.h

@@ -410,6 +410,7 @@ enum msgtype {
 	MSG_IDENTIFY_CWD,
 
 #ifdef TMATE_SLAVE
+	/* Next time put this after TMATE_LATENCY */
 	MSG_IDENTIFY_TMATE_IP_ADDRESS,
 	MSG_IDENTIFY_TMATE_PUBKEY,
 	MSG_IDENTIFY_TMATE_READONLY,
@@ -432,6 +433,10 @@ enum msgtype {
 	MSG_SUSPEND,
 	MSG_UNLOCK,
 	MSG_WAKEUP,
+
+#ifdef TMATE_SLAVE
+	MSG_LATENCY = 300
+#endif
 };
 
 /*