fix handling of TCP timeouts

when a TCP dispatch times out, we call tcp_recv() with a result
value of ISC_R_TIMEDOUT; this cancels the oldest dispatch
entry in the dispatch's active queue, plus any additional entries
that have waited longer than their configured timeouts. if, at
that point, there were more dispatch entries still on the active
queue, it resumes reading, but until now it failed to restart
the timer.

this has been corrected: we now calculate a new timeout
based on the oldest dispatch entry still remaining.  this
requires us to initialize the start time of each dispatch entry
when it's first added to the queue.

in order to ensure that the handling of timed-out requests is
consistent, we now calculate the runtime of each dispatch
entry based on the same value for 'now'.

incidentally also fixed a compile error that turned up when
DNS_DISPATCH_TRACE was turned on.

diff --git a/lib/dns/dispatch.c b/lib/dns/dispatch.c
index c3006b6501cee3a9e1f6ab93ac15749fefb82d84..3c9f8f55aca42fa3d9f06f8c00113c93f0174470 100644 (file)
--- a/lib/dns/dispatch.c
+++ b/lib/dns/dispatch.c
@@ -207,6 +207,8 @@ qid_destroy(isc_mem_t *mctx, dns_qid_t **qidp);
 static void
 udp_startrecv(isc_nmhandle_t *handle, dns_dispentry_t *resp);
 static void
+udp_dispatch_connect(dns_dispatch_t *disp, dns_dispentry_t *resp);
+static void
 tcp_startrecv(dns_dispatch_t *disp, dns_dispentry_t *resp);
 static void
 tcp_dispatch_getnext(dns_dispatch_t *disp, dns_dispentry_t *resp,
@@ -490,19 +492,15 @@ ISC_REFCOUNT_IMPL(dns_dispentry, dispentry_destroy);
 
 /*
  * How long in milliseconds has it been since this dispentry
- * started reading? (Only used for UDP, to adjust the timeout
- * downward when running getnext.)
+ * started reading?
  */
 static unsigned int
-dispentry_runtime(dns_dispentry_t *resp) {
-       isc_time_t now;
-
+dispentry_runtime(dns_dispentry_t *resp, const isc_time_t *now) {
        if (isc_time_isepoch(&resp->start)) {
                return (0);
        }
 
-       now = isc_time_now();
-       return (isc_time_microdiff(&now, &resp->start) / 1000);
+       return (isc_time_microdiff(now, &resp->start) / 1000);
 }
 
 /*
@@ -532,6 +530,7 @@ udp_recv(isc_nmhandle_t *handle, isc_result_t eresult, isc_region_t *region,
        isc_netaddr_t netaddr;
        int match, timeout = 0;
        bool respond = true;
+       isc_time_t now;
 
        REQUIRE(VALID_RESPONSE(resp));
        REQUIRE(VALID_DISPATCH(resp->disp));
@@ -631,7 +630,8 @@ next:
         * This is the wrong response.  Check whether there is still enough
         * time to wait for the correct one to arrive before the timeout fires.
         */
-       timeout = resp->timeout - dispentry_runtime(resp);
+       now = isc_time_now();
+       timeout = resp->timeout - dispentry_runtime(resp, &now);
        if (timeout <= 0) {
                /*
                 * The time window for receiving the correct response is
@@ -803,6 +803,8 @@ tcp_recv(isc_nmhandle_t *handle, isc_result_t result, isc_region_t *region,
        char buf[ISC_SOCKADDR_FORMATSIZE];
        isc_sockaddr_t peer;
        dns_displist_t resps = ISC_LIST_INITIALIZER;
+       isc_time_t now = isc_time_now();
+       int timeout;
 
        REQUIRE(VALID_DISPATCH(disp));
 
@@ -862,8 +864,7 @@ tcp_recv(isc_nmhandle_t *handle, isc_result_t result, isc_region_t *region,
        for (resp = ISC_LIST_HEAD(disp->active); resp != NULL; resp = next) {
                next = ISC_LIST_NEXT(resp, alink);
 
-               /* FIXME: dispentry_runtime is always 0 for TCP */
-               int timeout = resp->timeout - dispentry_runtime(resp);
+               timeout = resp->timeout - dispentry_runtime(resp, &now);
                if (timeout <= 0) {
                        tcp_recv_add(&resps, resp, ISC_R_TIMEDOUT);
                }
@@ -900,8 +901,12 @@ tcp_recv(isc_nmhandle_t *handle, isc_result_t result, isc_region_t *region,
        /*
         * Phase 5: Resume reading if there are still active responses
         */
-       if (!ISC_LIST_EMPTY(disp->active)) {
-               tcp_startrecv(disp, ISC_LIST_HEAD(disp->active));
+       resp = ISC_LIST_HEAD(disp->active);
+       if (resp != NULL) {
+               timeout = resp->timeout - dispentry_runtime(resp, &now);
+               INSIST(timeout > 0);
+               tcp_startrecv(disp, resp);
+               isc_nmhandle_settimeout(handle, timeout);
        }
 
        UNLOCK(&disp->lock);
@@ -1485,7 +1490,7 @@ dns_dispatch_add(dns_dispatch_t *disp, unsigned int options,
 
 #if DNS_DISPATCH_TRACE
        fprintf(stderr, "dns_dispentry__init:%s:%s:%d:%p->references = 1\n",
-               __func__, __FILE__, __LINE__, res);
+               __func__, __FILE__, __LINE__, resp);
 #endif
        isc_refcount_init(&resp->references, 1); /* DISPENTRY000 */
 
@@ -1576,24 +1581,23 @@ dns_dispatch_getnext(dns_dispentry_t *resp) {
 
        dispentry_log(resp, LVL(90), "getnext for QID %d", resp->id);
 
+       isc_time_t now = isc_time_now();
+       timeout = resp->timeout - dispentry_runtime(resp, &now);
+       if (timeout <= 0) {
+               return (ISC_R_TIMEDOUT);
+       }
+
        LOCK(&disp->lock);
        switch (disp->socktype) {
-       case isc_socktype_udp: {
-               timeout = resp->timeout - dispentry_runtime(resp);
-               if (timeout <= 0) {
-                       result = ISC_R_TIMEDOUT;
-                       break;
-               }
+       case isc_socktype_udp:
                udp_dispatch_getnext(resp, timeout);
                break;
-       }
        case isc_socktype_tcp:
                tcp_dispatch_getnext(disp, resp, timeout);
                break;
        default:
                UNREACHABLE();
        }
-
        UNLOCK(&disp->lock);
 
        return (result);
@@ -1801,7 +1805,6 @@ static void
 udp_startrecv(isc_nmhandle_t *handle, dns_dispentry_t *resp) {
        REQUIRE(VALID_RESPONSE(resp));
 
-       resp->start = isc_time_now();
        dispentry_log(resp, LVL(90), "attaching handle %p to %p", handle,
                      &resp->handle);
        isc_nmhandle_attach(handle, &resp->handle);
@@ -1819,6 +1822,7 @@ tcp_startrecv(dns_dispatch_t *disp, dns_dispentry_t *resp) {
        dns_dispatch_ref(disp); /* DISPATCH002 */
        if (resp != NULL) {
                dispentry_log(resp, LVL(90), "reading from %p", disp->handle);
+               INSIST(!isc_time_isepoch(&resp->start));
        } else {
                dispatch_log(disp, LVL(90),
                             "TCP reading without response from %p",
@@ -1908,9 +1912,6 @@ tcp_connected(isc_nmhandle_t *handle, isc_result_t eresult, void *arg) {
        dns_dispatch_detach(&disp); /* DISPATCH003 */
 }
 
-static void
-udp_dispatch_connect(dns_dispatch_t *disp, dns_dispentry_t *resp);
-
 static void
 udp_connected(isc_nmhandle_t *handle, isc_result_t eresult, void *arg) {
        dns_dispentry_t *resp = (dns_dispentry_t *)arg;
@@ -1974,9 +1975,11 @@ static void
 udp_dispatch_connect(dns_dispatch_t *disp, dns_dispentry_t *resp) {
        LOCK(&disp->lock);
        resp->state = DNS_DISPATCHSTATE_CONNECTING;
+       resp->start = isc_time_now();
        dns_dispentry_ref(resp); /* DISPENTRY004 */
        ISC_LIST_APPEND(disp->pending, resp, plink);
        UNLOCK(&disp->lock);
+
        isc_nm_udpconnect(disp->mgr->nm, &resp->local, &resp->peer,
                          udp_connected, resp, resp->timeout);
 }
@@ -2011,6 +2014,7 @@ tcp_dispatch_connect(dns_dispatch_t *disp, dns_dispentry_t *resp) {
                /* First connection, continue with connecting */
                disp->state = DNS_DISPATCHSTATE_CONNECTING;
                resp->state = DNS_DISPATCHSTATE_CONNECTING;
+               resp->start = isc_time_now();
                dns_dispentry_ref(resp); /* DISPENTRY005 */
                ISC_LIST_APPEND(disp->pending, resp, plink);
                UNLOCK(&disp->lock);
@@ -2036,6 +2040,7 @@ tcp_dispatch_connect(dns_dispatch_t *disp, dns_dispentry_t *resp) {
        case DNS_DISPATCHSTATE_CONNECTING:
                /* Connection pending; add resp to the list */
                resp->state = DNS_DISPATCHSTATE_CONNECTING;
+               resp->start = isc_time_now();
                dns_dispentry_ref(resp); /* DISPENTRY005 */
                ISC_LIST_APPEND(disp->pending, resp, plink);
                UNLOCK(&disp->lock);
@@ -2043,6 +2048,7 @@ tcp_dispatch_connect(dns_dispatch_t *disp, dns_dispentry_t *resp) {
 
        case DNS_DISPATCHSTATE_CONNECTED:
                resp->state = DNS_DISPATCHSTATE_CONNECTED;
+               resp->start = isc_time_now();
 
                /* Add the resp to the reading list */
                ISC_LIST_APPEND(disp->active, resp, alink);