changeset 22252:8882a5cbe76d

director: Use more accurate timestamps for handshake timeout logging There could be some time between the create, connect and when ME was received.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Wed, 31 May 2017 13:17:37 +0300
parents dce18ed41532
children 9676f01a11df
files src/director/director-connection.c
diffstat 1 files changed, 17 insertions(+), 10 deletions(-) [+]
line wrap: on
line diff
--- a/src/director/director-connection.c	Wed May 31 13:15:04 2017 +0300
+++ b/src/director/director-connection.c	Wed May 31 13:17:37 2017 +0300
@@ -98,7 +98,7 @@
 struct director_connection {
 	struct director *dir;
 	char *name;
-	time_t created;
+	struct timeval created, connected_time, me_received_time;
 	unsigned int minor_version;
 
 	struct timeval last_input, last_output;
@@ -161,18 +161,22 @@
 static void
 director_connection_init_timeout(struct director_connection *conn)
 {
-	unsigned int secs = ioloop_time - conn->created;
+	unsigned int secs;
 
 	if (!conn->connected) {
+		secs = ioloop_time - conn->created.tv_sec;
 		i_error("director(%s): Connect timed out (%u secs)",
 			conn->name, secs);
 	} else if (!conn->me_received) {
+		secs = ioloop_time - conn->connected_time.tv_sec;
 		i_error("director(%s): Handshaking ME timed out (%u secs)",
 			conn->name, secs);
 	} else if (!conn->in) {
+		secs = ioloop_time - conn->me_received_time.tv_sec;
 		i_error("director(%s): Sending handshake timed out (%u secs)",
 			conn->name, secs);
 	} else {
+		secs = ioloop_time - conn->me_received_time.tv_sec;
 		i_error("director(%s): Handshaking DONE timed out (%u secs)",
 			conn->name, secs);
 	}
@@ -412,6 +416,7 @@
 		return FALSE;
 	}
 	conn->me_received = TRUE;
+	conn->me_received_time = ioloop_timeval;
 
 	if (args[2] != NULL) {
 		time_t remote_time;
@@ -1239,7 +1244,7 @@
 static bool director_handshake_cmd_done(struct director_connection *conn)
 {
 	struct director *dir = conn->dir;
-	unsigned int handshake_secs = time(NULL) - conn->created;
+	int handshake_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->connected_time);
 	string_t *str;
 
 	if (conn->users_unsorted && conn->user_iter == NULL) {
@@ -1249,11 +1254,11 @@
 	}
 
 	str = t_str_new(128);
-	str_printfa(str, "director(%s): Handshake finished in %u secs "
+	str_printfa(str, "director(%s): Handshake finished in %u.%03u secs "
 		    "(bytes in=%"PRIuUOFF_T" out=%"PRIuUOFF_T")",
-		    conn->name, handshake_secs, conn->input->v_offset,
-		    conn->output->offset);
-	if (handshake_secs >= DIRECTOR_HANDSHAKE_WARN_SECS)
+		    conn->name, handshake_msecs/1000, handshake_msecs%1000,
+		    conn->input->v_offset, conn->output->offset);
+	if (handshake_msecs >= DIRECTOR_HANDSHAKE_WARN_SECS*1000)
 		i_warning("%s", str_c(str));
 	else
 		i_info("%s", str_c(str));
@@ -1722,7 +1727,7 @@
 director_connection_log_disconnect(struct director_connection *conn, int err,
 				   const char *errstr)
 {
-	unsigned int secs = ioloop_time - conn->created;
+	unsigned int secs = ioloop_time - conn->connected_time.tv_sec;
 	string_t *str = t_str_new(128);
 
 	i_assert(conn->connected);
@@ -1950,7 +1955,7 @@
 	struct director_connection *conn;
 
 	conn = i_new(struct director_connection, 1);
-	conn->created = ioloop_time;
+	conn->created = ioloop_timeval;
 	conn->fd = fd;
 	conn->dir = dir;
 	conn->input = i_stream_create_fd(conn->fd, MAX_INBUF_SIZE, FALSE);
@@ -1979,6 +1984,7 @@
 	conn = director_connection_init_common(dir, fd);
 	conn->in = TRUE;
 	conn->connected = TRUE;
+	conn->connected_time = ioloop_timeval;
 	conn->name = i_strdup_printf("%s/in", net_ip2addr(ip));
 	conn->io = io_add(conn->fd, IO_READ, director_connection_input, conn);
 	conn->to_ping = timeout_add(DIRECTOR_CONNECTION_ME_TIMEOUT_MSECS,
@@ -1998,6 +2004,7 @@
 		director_connection_disconnected(&conn, strerror(err));
 		return;
 	}
+	conn->connected_time = ioloop_timeval;
 	conn->connected = TRUE;
 	o_stream_set_flush_callback(conn->output,
 				    director_connection_output, conn);
@@ -2130,7 +2137,7 @@
 	struct director_connection *conn = *_conn;
 	struct director *dir = conn->dir;
 
-	if (conn->created + DIRECTOR_SUCCESS_MIN_CONNECT_SECS > ioloop_time &&
+	if (conn->connected_time.tv_sec + DIRECTOR_SUCCESS_MIN_CONNECT_SECS > ioloop_time &&
 	    conn->host != NULL) {
 		/* connection didn't exist for very long, assume it has a
 		   network problem */