From: Timo Sirainen <timo.sirainen@dovecot.fi>
Date: Wed, 30 Nov 2016 13:59:01 +0000 (+0200)
Subject: dict-client: Don't timeout lookups without waiting 1sec in dict ioloop.
X-Git-Tag: 2.3.0.rc1~2474
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=d640b628f27c9bbcbf6fe902b257002a3f0da57b;p=thirdparty%2Fdovecot%2Fcore.git

dict-client: Don't timeout lookups without waiting 1sec in dict ioloop.

What could have happened was:

 - dict-client sends a request to dict-server
 - dict-client process starts doing something else
 - dict-server answers
 - dict-client process continues doing something else for over 30 seconds,
   not reading the dict-server answer
 - dict-client process gets back to dict ioloop, which runs the timeout
   before checking if there is anything available for reading.

Now we'll wait for 1 second in the last dict ioloop before assuming that
there's a timeout.
---

diff --git a/src/lib-dict/dict-client.c b/src/lib-dict/dict-client.c
index 9f58694306..d2e411d025 100644
--- a/src/lib-dict/dict-client.c
+++ b/src/lib-dict/dict-client.c
@@ -25,6 +25,9 @@
 
 /* Abort dict lookup after this many seconds. */
 #define DICT_CLIENT_REQUEST_TIMEOUT_MSECS 30000
+/* When dict lookup timeout is reached, wait a bit longer if the last dict
+   ioloop wait was shorter than this. */
+#define DICT_CLIENT_REQUEST_TIMEOUT_MIN_LAST_IOLOOP_WAIT_MSECS 1000
 /* Log a warning if dict lookup takes longer than this many milliseconds. */
 #define DICT_CLIENT_DEFAULT_WARN_SLOW_MSECS 5000
 
@@ -78,6 +81,7 @@ struct client_dict {
 
 	struct ioloop *ioloop, *prev_ioloop;
 	struct io_wait_timer *wait_timer;
+	uint64_t last_timer_switch_usecs;
 	struct timeout *to_requests;
 	struct timeout *to_idle;
 	unsigned int idle_msecs;
@@ -237,6 +241,7 @@ static void client_dict_input_timeout(struct client_dict *dict)
 {
 	struct client_dict_cmd *cmd;
 	const char *error;
+	uint64_t msecs_in_last_dict_ioloop_wait;
 	int cmd_diff;
 
 	/* find the first non-background command. there must be at least one. */
@@ -255,6 +260,21 @@ static void client_dict_input_timeout(struct client_dict *dict)
 		return;
 	}
 
+	/* If we've gotten here because all the time was spent in other ioloops
+	   or locks, make sure there's a bit of time waiting for the dict
+	   ioloop as well. There's a good chance that the reply can be read. */
+	msecs_in_last_dict_ioloop_wait =
+		(io_wait_timer_get_usecs(dict->wait_timer) -
+		 dict->last_timer_switch_usecs + 999) / 1000;
+	if (msecs_in_last_dict_ioloop_wait < DICT_CLIENT_REQUEST_TIMEOUT_MIN_LAST_IOLOOP_WAIT_MSECS) {
+		timeout_remove(&dict->to_requests);
+		dict->to_requests =
+			timeout_add(DICT_CLIENT_REQUEST_TIMEOUT_MIN_LAST_IOLOOP_WAIT_MSECS -
+				    msecs_in_last_dict_ioloop_wait,
+				    client_dict_input_timeout, dict);
+		return;
+	}
+
 	(void)client_dict_reconnect(dict, t_strdup_printf(
 		"Dict server timeout: %s "
 		"(%u commands pending, oldest sent %u.%03u secs ago: %s, %s)",
@@ -823,6 +843,8 @@ static bool client_dict_switch_ioloop(struct dict *_dict)
 {
 	struct client_dict *dict = (struct client_dict *)_dict;
 
+	dict->last_timer_switch_usecs =
+		io_wait_timer_get_usecs(dict->wait_timer);
 	dict->wait_timer = io_wait_timer_move(&dict->wait_timer);
 	if (dict->to_idle != NULL)
 		dict->to_idle = io_loop_move_timeout(&dict->to_idle);