changeset 21257:a6395b1f1fad

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.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Wed, 30 Nov 2016 15:59:01 +0200
parents 4ac3461df334
children f50c3b9dfbba
files src/lib-dict/dict-client.c
diffstat 1 files changed, 22 insertions(+), 0 deletions(-) [+]
line wrap: on
line diff
--- a/src/lib-dict/dict-client.c	Thu Dec 01 19:06:10 2016 +0200
+++ b/src/lib-dict/dict-client.c	Wed Nov 30 15:59:01 2016 +0200
@@ -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 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 @@
 {
 	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 @@
 		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)",
@@ -824,6 +844,8 @@
 {
 	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);