# HG changeset patch
# User Timo Sirainen <timo.sirainen@dovecot.fi>
# Date 1450864092 -7200
# Node ID 3df66d89a87a3dd0267f251859e6602bd1cadd11
# Parent  6e6a4b294fbd28be45b9826c4d4ebec1a1c90afa
lib-http: Add more timing information to debug logs when HTTP connections get closed.

diff -r 6e6a4b294fbd -r 3df66d89a87a src/lib-http/http-client-connection.c
--- a/src/lib-http/http-client-connection.c	Thu Dec 17 05:52:03 2015 +0200
+++ b/src/lib-http/http-client-connection.c	Wed Dec 23 11:48:12 2015 +0200
@@ -121,6 +121,38 @@
 	http_client_connection_close(_conn);
 }
 
+static const char *
+http_client_connection_get_timing_info(struct http_client_connection *conn)
+{
+	struct http_client_request *const *requestp;
+	unsigned int sent_msecs, total_msecs, connected_msecs;
+	string_t *str = t_str_new(64);
+
+	if (array_count(&conn->request_wait_list) > 0) {
+		requestp = array_idx(&conn->request_wait_list, 0);
+		sent_msecs = timeval_diff_msecs(&ioloop_timeval, &(*requestp)->sent_time);
+		total_msecs = timeval_diff_msecs(&ioloop_timeval, &(*requestp)->submit_time);
+
+		str_printfa(str, "Request sent %u.%03u secs ago",
+			    sent_msecs/1000, sent_msecs%1000);
+		if ((*requestp)->attempts > 0) {
+			str_printfa(str, ", %u attempts in %u.%03u secs",
+				    (*requestp)->attempts + 1,
+				    total_msecs/1000, total_msecs%1000);
+		}
+	} else {
+		str_append(str, "No requests");
+		if (conn->conn.last_input != 0) {
+			str_printfa(str, ", last input %d secs ago",
+				    (int)(ioloop_time - conn->conn.last_input));
+		}
+	}
+	connected_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->connected_timestamp);
+	str_printfa(str, ", connected %u.%03u secs ago",
+		    connected_msecs/1000, connected_msecs%1000);
+	return str_c(str);
+}
+
 static void
 http_client_connection_abort_temp_error(struct http_client_connection **_conn,
 	unsigned int status, const char *error)
@@ -144,6 +176,8 @@
 			return;
 		}
 	}
+	error = t_strdup_printf("%s (%s)", error,
+				http_client_connection_get_timing_info(conn));
 
 	http_client_connection_debug(conn,
 		"Aborting connection with temporary error: %s", error);
@@ -257,24 +291,9 @@
 static void
 http_client_connection_request_timeout(struct http_client_connection *conn)
 {
-	struct http_client_request *const *requestp;
-	unsigned int timeout_msecs, total_msecs;
-	string_t *str = t_str_new(64);
-
-	requestp = array_idx(&conn->request_wait_list, 0);
-	timeout_msecs = timeval_diff_msecs(&ioloop_timeval, &(*requestp)->sent_time);
-	total_msecs = timeval_diff_msecs(&ioloop_timeval, &(*requestp)->submit_time);
-
-	str_printfa(str, "No response for request in %u.%03u secs",
-		    timeout_msecs/1000, timeout_msecs%1000);
-	if ((*requestp)->attempts > 0) {
-		str_printfa(str, " (%u attempts in %u.%03u secs)",
-			    (*requestp)->attempts + 1,
-			    total_msecs/1000, total_msecs%1000);
-	}
 	conn->conn.input->stream_errno = ETIMEDOUT;
 	http_client_connection_abort_temp_error(&conn,
-		HTTP_CLIENT_REQUEST_ERROR_TIMED_OUT, str_c(str));
+		HTTP_CLIENT_REQUEST_ERROR_TIMED_OUT, "Request timed out");
 }
 
 void http_client_connection_start_request_timeout(
@@ -597,6 +616,8 @@
 
 	i_assert(conn->incoming_payload == NULL);
 
+	_conn->last_input = ioloop_time;
+
 	if (conn->ssl_iostream != NULL &&
 		!ssl_iostream_is_handshaked(conn->ssl_iostream)) {
 		/* finish SSL negotiation by reading from input stream */