Merge pull request #282 from wtoorop/bugfix/issue-272

Bugfix/issue 272

configure.ac

@@ -149,15 +149,16 @@ fi
 ])
 ACX_ARG_RPATH
 
-
+AC_ARG_ENABLE(debug-req, AC_HELP_STRING([--enable-debug-req], [Enable request debugging]))
 AC_ARG_ENABLE(debug-sched, AC_HELP_STRING([--enable-debug-sched], [Enable scheduling debugging messages]))
 AC_ARG_ENABLE(debug-stub, AC_HELP_STRING([--enable-debug-stub], [Enable stub debugging messages]))
 AC_ARG_ENABLE(debug-daemon, AC_HELP_STRING([--enable-debug-daemon], [Enable daemon debugging messages]))
 AC_ARG_ENABLE(debug-sec, AC_HELP_STRING([--enable-debug-sec], [Enable dnssec debugging messages]))
 AC_ARG_ENABLE(debug-server, AC_HELP_STRING([--enable-debug-server], [Enable server debugging messages]))
-AC_ARG_ENABLE(all-debugging, AC_HELP_STRING([--enable-all-debugging], [Enable scheduling, stub and dnssec debugging]))
+AC_ARG_ENABLE(all-debugging, AC_HELP_STRING([--enable-all-debugging], [Enable all debugging messages]))
 case "$enable_all_debugging" in
 	yes)
+		enable_debug_req=yes
 		enable_debug_sched=yes
 		enable_debug_stub=yes
 		enable_debug_daemon=yes
@@ -167,6 +168,13 @@ case "$enable_all_debugging" in
 	no|*)
 		;;
 esac
+case "$enable_debug_req" in
+	yes)
+		AC_DEFINE_UNQUOTED([REQ_DEBUG], [1], [Define this to enable printing of request debugging messages.])
+		;;
+	no|*)
+		;;
+esac
 case "$enable_debug_sched" in
 	yes)
 		AC_DEFINE_UNQUOTED([SCHED_DEBUG], [1], [Define this to enable printing of scheduling debugging messages.])

src/context.c

@@ -691,7 +691,10 @@ _getdns_upstreams_dereference(getdns_upstreams *upstreams)
 		while (upstream->finished_dnsreqs) {
 			dnsreq = upstream->finished_dnsreqs;
 			upstream->finished_dnsreqs = dnsreq->finished_next;
-			_getdns_context_cancel_request(dnsreq);
+			if (!dnsreq->internal_cb) { /* Not part of chain */
+				debug_req("Destroy    ", *dnsreq->netreqs);
+				_getdns_context_cancel_request(dnsreq);
+			}
 		}
 		if (upstream->tls_session != NULL)
 			SSL_SESSION_free(upstream->tls_session);
@@ -3080,13 +3083,17 @@ getdns_cancel_callback(getdns_context *context,
 
 	getdns_context_request_count_changed(context);
 
+	debug_req("CB Cancel  ", *dnsreq->netreqs);
 	if (dnsreq->user_callback) {
 		dnsreq->context->processing = 1;
 		dnsreq->user_callback(dnsreq->context, GETDNS_CALLBACK_CANCEL,
 		    NULL, dnsreq->user_pointer, dnsreq->trans_id);
 		dnsreq->context->processing = 0;
 	}
-	_getdns_context_cancel_request(dnsreq);
+	if (!dnsreq->internal_cb) { /* Not part of chain */
+		debug_req("Destroy    ", *dnsreq->netreqs);
+		_getdns_context_cancel_request(dnsreq);
+	}
 	return GETDNS_RETURN_GOOD;
 } /* getdns_cancel_callback */
 
@@ -3095,6 +3102,7 @@ _getdns_context_request_timed_out(getdns_dns_req *dnsreq)
 {
 	DEBUG_SCHED("%s(%p)\n", __FUNC__, (void *)dnsreq);
 
+	debug_req("CB Timeout ", *dnsreq->netreqs);
 	if (dnsreq->user_callback) {
 		dnsreq->context->processing = 1;
 		dnsreq->user_callback(dnsreq->context, GETDNS_CALLBACK_TIMEOUT,

src/debug.h

@@ -36,7 +36,6 @@
 #define DEBUG_H
 
 #include "config.h"
-
 #define STUB_DEBUG_ENTRY     "=> ENTRY:       "
 #define STUB_DEBUG_SETUP     "--- SETUP:      "
 #define STUB_DEBUG_SETUP_TLS "--- SETUP(TLS): "
@@ -91,6 +90,31 @@
 
 #define DEBUG_OFF(...) do {} while (0)
 
+#if defined(REQ_DEBUG) && REQ_DEBUG
+#include <time.h>
+#define DEBUG_REQ(...) DEBUG_ON(__VA_ARGS__)
+#include "gldns/wire2str.h"
+#include "rr-dict.h"
+#include "types-internal.h"
+static inline void debug_req(const char *msg, getdns_network_req *netreq)
+{
+	char str[1024];
+	struct timeval tv;
+	uint64_t t;
+
+	(void) gettimeofday(&tv, NULL);
+	t = tv.tv_sec * 1000 + tv.tv_usec / 1000;
+	t = t >= netreq->owner->expires ? 0 : netreq->owner->expires - t;
+	(void) gldns_wire2str_dname_buf(netreq->owner->name,
+	    netreq->owner->name_len, str, sizeof(str));
+	DEBUG_REQ("NETREQ %s %4"PRIu64" %s %s\n", msg, t,
+	    str, _getdns_rr_type_name(netreq->request_type));
+}
+#else
+#define DEBUG_REQ(...) DEBUG_OFF(__VA_ARGS__)
+#define debug_req(...) DEBUG_OFF(__VA_ARGS__)
+#endif
+
 #if defined(SCHED_DEBUG) && SCHED_DEBUG
 #include <time.h>
 #define DEBUG_SCHED(...) DEBUG_ON(__VA_ARGS__)
@@ -139,7 +163,8 @@
 #define DEBUG_MDNS(...) DEBUG_OFF(__VA_ARGS__)
 #endif
 
-#if (defined(SCHED_DEBUG)  && SCHED_DEBUG)  || \
+#if (defined(REQ_DEBUG)    && REQ_DEBUG)    || \
+    (defined(SCHED_DEBUG)  && SCHED_DEBUG)  || \
     (defined(STUB_DEBUG)   && STUB_DEBUG)   || \
     (defined(DAEMON_DEBUG) && DAEMON_DEBUG) || \
     (defined(SEC_DEBUG)    && SEC_DEBUG)    || \

src/dnssec.c

@@ -3113,6 +3113,43 @@ static void check_chain_complete(chain_head *chain)
 	_getdns_call_user_callback(dnsreq, response_dict);
 }
 
+void _getdns_validation_chain_timeout(getdns_dns_req *dnsreq)
+{
+	chain_head *head = dnsreq->chain, *next;
+	chain_node *node;
+	size_t      node_count;
+
+	while (head) {
+		next = head->next;
+
+		for ( node_count = head->node_count, node = head->parent
+		    ; node_count
+		    ; node_count--, node = node->parent ) {
+
+			if (!_getdns_netreq_finished(node->dnskey_req)) {
+				_getdns_context_cancel_request(
+				    node->dnskey_req->owner);
+				node->dnskey_req = NULL;
+			}
+
+			if (!_getdns_netreq_finished(node->ds_req)) {
+				_getdns_context_cancel_request(
+				    node->ds_req->owner);
+				node->ds_req = NULL;
+			}
+
+			if (!_getdns_netreq_finished(node->soa_req)) {
+				_getdns_context_cancel_request(
+				    node->soa_req->owner);
+				node->soa_req = NULL;
+			}
+		}
+		head = next;
+	}
+	dnsreq->request_timed_out = 1;
+	check_chain_complete(dnsreq->chain);
+}
+
 void _getdns_cancel_validation_chain(getdns_dns_req *dnsreq)
 {
 	chain_head *head = dnsreq->chain, *next;

src/dnssec.h

@@ -47,6 +47,7 @@
 /* Do some additional requests to fetch the complete validation chain */
 void _getdns_get_validation_chain(getdns_dns_req *dns_req);
 void _getdns_cancel_validation_chain(getdns_dns_req *dns_req);
+void _getdns_validation_chain_timeout(getdns_dns_req *dns_req);
 
 uint16_t _getdns_parse_ta_file(time_t *ta_mtime, gldns_buffer *gbuf);
 

src/general.c

@@ -53,6 +53,7 @@
 #include "stub.h"
 #include "dict.h"
 #include "mdns.h"
+#include "debug.h"
 
 void _getdns_call_user_callback(getdns_dns_req *dnsreq, getdns_dict *response)
 {
@@ -61,8 +62,9 @@ void _getdns_call_user_callback(getdns_dns_req *dnsreq, getdns_dict *response)
 	if (dnsreq->user_callback) {
 		dnsreq->context->processing = 1;
 		dnsreq->user_callback(dnsreq->context,
-		    (response ? GETDNS_CALLBACK_COMPLETE
+		    ( ! response                ? GETDNS_CALLBACK_ERROR
-		              : GETDNS_CALLBACK_ERROR),
+		    : dnsreq->request_timed_out ? GETDNS_CALLBACK_TIMEOUT
+		                                : GETDNS_CALLBACK_COMPLETE ),
 		    response, dnsreq->user_pointer, dnsreq->trans_id);
 		dnsreq->context->processing = 0;
 	}
@@ -186,6 +188,14 @@ _getdns_check_dns_req_complete(getdns_dns_req *dns_req)
 			return;
 		}
 	}
+#if defined(REQ_DEBUG) && REQ_DEBUG
+	if (dns_req->internal_cb)
+		debug_req("CB Internal", *dns_req->netreqs);
+	else if (results_found)
+		debug_req("CB Complete", *dns_req->netreqs);
+	else
+		debug_req("CB Error   ", *dns_req->netreqs);
+#endif
 	if (dns_req->internal_cb) {
 		_getdns_context_clear_outbound_request(dns_req);
 		dns_req->internal_cb(dns_req);
@@ -206,9 +216,20 @@ _getdns_check_dns_req_complete(getdns_dns_req *dns_req)
 	            dns_req->dnssec_return_all_statuses
 	           ))
 #endif
-	    ))
+	    )) {
+		/* Reschedule timeout for this DNS request
+		 */
+		if (dns_req->timeout.timeout_cb && dns_req->timeout.ev)
+			GETDNS_CLEAR_EVENT(dns_req->loop, &dns_req->timeout);
+
+		GETDNS_SCHEDULE_EVENT(dns_req->loop, -1,
+		    _getdns_ms_until_expiry2(dns_req->expires, &now_ms),
+		    getdns_eventloop_event_init(&dns_req->timeout, dns_req,
+		    NULL, NULL, (getdns_eventloop_callback)
+		    _getdns_validation_chain_timeout));
+
 		_getdns_get_validation_chain(dns_req);
-	else
+	} else
 		_getdns_call_user_callback(
 		    dns_req, _getdns_create_getdns_response(dns_req));
 }
@@ -373,6 +394,8 @@ _getdns_submit_netreq(getdns_network_req *netreq, uint64_t *now_ms)
 	}
 	_getdns_netreq_change_state(netreq, NET_REQ_IN_FLIGHT);
 
+	debug_req("Submitting ", netreq);
+
 #ifdef STUB_NATIVE_DNSSEC
 # ifdef DNSSEC_ROADBLOCK_AVOIDANCE
 

src/request-internal.c

@@ -944,6 +944,7 @@ _getdns_dns_req_new(getdns_context *context, getdns_eventloop *loop,
 	result->freed = NULL;
 	result->validating = 0;
 	result->is_dns_request = 1;
+	result->request_timed_out = 0;
 	result->chain = NULL;
 
 	network_req_init(result->netreqs[0], result,

src/stub.c

@@ -32,6 +32,12 @@
  */
 
 #include "config.h"
+
+/* Intercept and do not sent out COM DS queries with TLS
+ * For debugging purposes only. Never commit with this turned on.
+ */
+#define INTERCEPT_COM_DS 0
+
 #ifdef USE_POLL_DEFAULT_EVENTLOOP
 # ifdef HAVE_SYS_POLL_H
 #  include <sys/poll.h>
@@ -1306,10 +1312,39 @@ stub_tls_write(getdns_upstream *upstream, getdns_tcp_state *tcp,
 		
 		/* TODO[TLS]: Handle error cases, partial writes, renegotiation etc. */
 		ERR_clear_error();
-		written = SSL_write(tls_obj, netreq->query - 2, pkt_len + 2);
+#if INTERCEPT_COM_DS
-		if (written <= 0)
+		/* Intercept and do not sent out COM DS queries. For debugging
-			return STUB_TCP_ERROR;
+		 * purposes only. Never commit with this turned on.
+		 */
+		if (netreq->request_type == GETDNS_RRTYPE_DS &&
+		    netreq->owner->name_len == 5 &&
+		    netreq->owner->name[0] == 3 &&
+		    (netreq->owner->name[1] & 0xDF) == 'C' &&
+		    (netreq->owner->name[2] & 0xDF) == 'O' &&
+		    (netreq->owner->name[3] & 0xDF) == 'M' &&
+		    netreq->owner->name[4] == 0) {
 
+			debug_req("Intercepting", netreq);
+			written = pkt_len + 2;
+		} else
+#endif
+		written = SSL_write(tls_obj, netreq->query - 2, pkt_len + 2);
+		if (written <= 0) {
+			/* SSL_write will not do partial writes, because 
+			 * SSL_MODE_ENABLE_PARTIAL_WRITE is not default,
+			 * but the write could fail because of renegotiation.
+			 * In that case SSL_get_error()  will return
+			 * SSL_ERROR_WANT_READ or, SSL_ERROR_WANT_WRITE.
+			 * Return for retry in such cases.
+			 */
+			switch (SSL_get_error(tls_obj, written)) {
+			case SSL_ERROR_WANT_READ:
+			case SSL_ERROR_WANT_WRITE:
+				return STUB_TCP_AGAIN;
+			default:
+				return STUB_TCP_ERROR;
+			}
+		}
 		/* We were able to write everything!  Start reading. */
 		return (int) query_id;
 
@@ -2080,6 +2115,12 @@ upstream_reschedule_events(getdns_upstream *upstream, uint64_t idle_timeout) {
 	else {
 		DEBUG_STUB("%s %-35s: FD:  %d Connection idle - timeout is %d\n", 
 			    STUB_DEBUG_SCHEDULE, __FUNC__, upstream->fd, (int)idle_timeout);
+		/* TODO: Schedule a read also anyway,
+		 *       to digest timed out answers.
+		 *       Dont forget to schedule with upstream->fd then!
+		 *
+		 * upstream->event.read_cb = upstream_read_cb;
+		 */
 		upstream->event.timeout_cb = upstream_idle_timeout_cb;
 		if (upstream->conn_state != GETDNS_CONN_OPEN)
 			idle_timeout = 0;

src/test/tpkg/070-coding-practice.tpkg/070-coding-practice.test

@@ -33,6 +33,19 @@ rm -f report.txt
 		echo ""
 	fi
 ) >> report.txt
+(
+ 	cd ${SRCROOT}/src
+	if [ `grep '^#define[ 	]*INTERCEPT_COM_DS[ 	]*1' stub.c | wc -l` -gt 0 ]
+	then
+		echo "*** "
+		echo "*** The repo contained the COM DS queries interception"
+		echo "*** with TLS transports turned on, this should be off"
+		echo "*** "
+		grep -n '^#define[ 	]INTERCEPT_COM_DS[ 	]*1' stub.c
+		echo ""
+	fi
+) >> report.txt
+
 
 if [ -s report.txt ]
 then

src/test/tpkg/225-stub-only-valgrind-checks.tpkg/225-stub-only-valgrind-checks.dsc

@@ -6,7 +6,7 @@ Maintainer: Willem Toorop
 Category: 
 Component:
 CmdDepends: valgrind
-Depends: 110-link.tpkg
+Depends: 210-stub-only-link.tpkg
 Help:
 Pre: 
 Post: 

src/types-internal.h

@@ -314,6 +314,7 @@ typedef struct getdns_dns_req {
 	unsigned dnssec_ok_checking_disabled		: 1;
 	unsigned is_sync_request			: 1;
 	unsigned is_dns_request				: 1;
+	unsigned request_timed_out			: 1;
 
 	/* The validating and freed variables are used to make sure a single
 	 * code path is followed while processing a DNS request, even when

src/util-internal.c

@@ -1263,6 +1263,7 @@ _getdns_create_getdns_response(getdns_dns_req *completed_request)
 		GETDNS_FREE(context->mf, srvs.rrs);
 	}
 	if (getdns_dict_set_int(result, GETDNS_STR_KEY_STATUS,
+	    completed_request->request_timed_out ||
 	    nreplies == 0   ? GETDNS_RESPSTATUS_ALL_TIMEOUT :
 	    completed_request->dnssec_return_only_secure && nsecure == 0 && ninsecure > 0
 	                    ? GETDNS_RESPSTATUS_NO_SECURE_ANSWERS :