From 2220c1a48d6a9bff27e2d3dd7572f3314c810f91 Mon Sep 17 00:00:00 2001 From: Willem Toorop Date: Wed, 5 Apr 2017 17:53:39 +0200 Subject: [PATCH 1/6] Options for request debugging --- configure.ac | 12 ++++++++++-- src/debug.h | 10 +++++++++- 2 files changed, 19 insertions(+), 3 deletions(-) diff --git a/configure.ac b/configure.ac index 43d653e3..bc07ab09 100644 --- a/configure.ac +++ b/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.]) diff --git a/src/debug.h b/src/debug.h index 9c5fa6f1..fff6b0cd 100644 --- a/src/debug.h +++ b/src/debug.h @@ -91,6 +91,13 @@ #define DEBUG_OFF(...) do {} while (0) +#if defined(REQ_DEBUG) && REQ_DEBUG +#include +#define DEBUG_REQ(...) DEBUG_ON(__VA_ARGS__) +#else +#define DEBUG_REQ(...) DEBUG_OFF(__VA_ARGS__) +#endif + #if defined(SCHED_DEBUG) && SCHED_DEBUG #include #define DEBUG_SCHED(...) DEBUG_ON(__VA_ARGS__) @@ -139,7 +146,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) || \ From f8c7d8b5d597c54119fd0d1aca64480fe4f6f680 Mon Sep 17 00:00:00 2001 From: Willem Toorop Date: Wed, 5 Apr 2017 22:43:27 +0200 Subject: [PATCH 2/6] Network request submission and callback reporting --- src/context.c | 3 +++ src/debug.h | 19 ++++++++++++++++++- src/general.c | 10 ++++++++++ 3 files changed, 31 insertions(+), 1 deletion(-) diff --git a/src/context.c b/src/context.c index 0748f40c..ca3603cf 100644 --- a/src/context.c +++ b/src/context.c @@ -691,6 +691,7 @@ _getdns_upstreams_dereference(getdns_upstreams *upstreams) while (upstream->finished_dnsreqs) { dnsreq = upstream->finished_dnsreqs; upstream->finished_dnsreqs = dnsreq->finished_next; + debug_req("Destroy ", *dnsreq->netreqs); _getdns_context_cancel_request(dnsreq); } if (upstream->tls_session != NULL) @@ -3080,6 +3081,7 @@ 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, @@ -3095,6 +3097,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, diff --git a/src/debug.h b/src/debug.h index fff6b0cd..fb74527c 100644 --- a/src/debug.h +++ b/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): " @@ -94,8 +93,26 @@ #if defined(REQ_DEBUG) && REQ_DEBUG #include #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 diff --git a/src/general.c b/src/general.c index cc6e1fe9..4ac4e3f2 100644 --- a/src/general.c +++ b/src/general.c @@ -186,6 +186,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); @@ -373,6 +381,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 From e08d3592a069c3ce8c6a51f88adebac6d7f3102f Mon Sep 17 00:00:00 2001 From: Willem Toorop Date: Thu, 6 Apr 2017 11:20:08 +0200 Subject: [PATCH 3/6] Schedule timeout when collecting for dnssec chain --- src/context.c | 11 ++++-- src/dnssec.c | 37 +++++++++++++++++++ src/dnssec.h | 1 + src/general.c | 22 +++++++++-- src/request-internal.c | 1 + src/stub.c | 22 +++++++++++ .../070-coding-practice.test | 13 +++++++ src/types-internal.h | 1 + src/util-internal.c | 1 + 9 files changed, 102 insertions(+), 7 deletions(-) diff --git a/src/context.c b/src/context.c index ca3603cf..2af25a3f 100644 --- a/src/context.c +++ b/src/context.c @@ -691,8 +691,10 @@ _getdns_upstreams_dereference(getdns_upstreams *upstreams) while (upstream->finished_dnsreqs) { dnsreq = upstream->finished_dnsreqs; upstream->finished_dnsreqs = dnsreq->finished_next; - debug_req("Destroy ", *dnsreq->netreqs); - _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); @@ -3088,7 +3090,10 @@ getdns_cancel_callback(getdns_context *context, 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 */ diff --git a/src/dnssec.c b/src/dnssec.c index b3e86bae..8c01a635 100644 --- a/src/dnssec.c +++ b/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; diff --git a/src/dnssec.h b/src/dnssec.h index b7becfe9..b0334d52 100644 --- a/src/dnssec.h +++ b/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); diff --git a/src/general.c b/src/general.c index 4ac4e3f2..16a07128 100644 --- a/src/general.c +++ b/src/general.c @@ -61,8 +61,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 - : GETDNS_CALLBACK_ERROR), + ( ! response ? GETDNS_CALLBACK_ERROR + : dnsreq->request_timed_out ? GETDNS_CALLBACK_TIMEOUT + : GETDNS_CALLBACK_COMPLETE ), response, dnsreq->user_pointer, dnsreq->trans_id); dnsreq->context->processing = 0; } @@ -214,9 +215,22 @@ _getdns_check_dns_req_complete(getdns_dns_req *dns_req) dns_req->dnssec_return_all_statuses )) #endif - )) + )) { + /* Reschedule timeout for this DNS request + */ + dns_req->timeout.userarg = dns_req; + dns_req->timeout.read_cb = NULL; + dns_req->timeout.write_cb = NULL; + dns_req->timeout.timeout_cb = + (getdns_eventloop_callback) + _getdns_validation_chain_timeout; + dns_req->timeout.ev = NULL; + (void) dns_req->loop->vmt->schedule(dns_req->loop, -1, + _getdns_ms_until_expiry2(dns_req->expires, &now_ms), + &dns_req->timeout); + _getdns_get_validation_chain(dns_req); - else + } else _getdns_call_user_callback( dns_req, _getdns_create_getdns_response(dns_req)); } diff --git a/src/request-internal.c b/src/request-internal.c index 1bd5475e..d91563f4 100644 --- a/src/request-internal.c +++ b/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, diff --git a/src/stub.c b/src/stub.c index 30c08091..90b44c96 100644 --- a/src/stub.c +++ b/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 @@ -1306,6 +1312,22 @@ stub_tls_write(getdns_upstream *upstream, getdns_tcp_state *tcp, /* TODO[TLS]: Handle error cases, partial writes, renegotiation etc. */ ERR_clear_error(); +#if INTERCEPT_COM_DS + /* Intercept and do not sent out COM DS queries. For debugging + * 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) return STUB_TCP_ERROR; diff --git a/src/test/tpkg/070-coding-practice.tpkg/070-coding-practice.test b/src/test/tpkg/070-coding-practice.tpkg/070-coding-practice.test index b628a657..09473687 100644 --- a/src/test/tpkg/070-coding-practice.tpkg/070-coding-practice.test +++ b/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 diff --git a/src/types-internal.h b/src/types-internal.h index 5e1961ac..e70d8911 100644 --- a/src/types-internal.h +++ b/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 diff --git a/src/util-internal.c b/src/util-internal.c index 33c31745..ddac7b51 100644 --- a/src/util-internal.c +++ b/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 : From 4ceec33d0826b9f5453875510735bf00d7ad8b75 Mon Sep 17 00:00:00 2001 From: Willem Toorop Date: Thu, 6 Apr 2017 11:46:10 +0200 Subject: [PATCH 4/6] Do something about TLS renegotiation. --- src/stub.c | 25 ++++++++++++++++++++++--- 1 file changed, 22 insertions(+), 3 deletions(-) diff --git a/src/stub.c b/src/stub.c index 90b44c96..e8a8ee52 100644 --- a/src/stub.c +++ b/src/stub.c @@ -1329,9 +1329,22 @@ stub_tls_write(getdns_upstream *upstream, getdns_tcp_state *tcp, } else #endif written = SSL_write(tls_obj, netreq->query - 2, pkt_len + 2); - if (written <= 0) - return STUB_TCP_ERROR; - + 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; @@ -2102,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; From e35a2182a92bf9f747471144c6ed2197cecbb729 Mon Sep 17 00:00:00 2001 From: Willem Toorop Date: Thu, 6 Apr 2017 12:24:27 +0200 Subject: [PATCH 5/6] missing #include --- src/general.c | 1 + 1 file changed, 1 insertion(+) diff --git a/src/general.c b/src/general.c index 16a07128..b981470b 100644 --- a/src/general.c +++ b/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) { From c2edc94a3a25e835e18e094aab6c080a489986e6 Mon Sep 17 00:00:00 2001 From: Willem Toorop Date: Thu, 6 Apr 2017 15:18:12 +0200 Subject: [PATCH 6/6] Clear timeout event when getting dnssec chain With full recursion --- src/general.c | 16 +++++++--------- .../225-stub-only-valgrind-checks.dsc | 2 +- 2 files changed, 8 insertions(+), 10 deletions(-) diff --git a/src/general.c b/src/general.c index b981470b..280df08d 100644 --- a/src/general.c +++ b/src/general.c @@ -219,16 +219,14 @@ _getdns_check_dns_req_complete(getdns_dns_req *dns_req) )) { /* Reschedule timeout for this DNS request */ - dns_req->timeout.userarg = dns_req; - dns_req->timeout.read_cb = NULL; - dns_req->timeout.write_cb = NULL; - dns_req->timeout.timeout_cb = - (getdns_eventloop_callback) - _getdns_validation_chain_timeout; - dns_req->timeout.ev = NULL; - (void) dns_req->loop->vmt->schedule(dns_req->loop, -1, + 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), - &dns_req->timeout); + 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 diff --git a/src/test/tpkg/225-stub-only-valgrind-checks.tpkg/225-stub-only-valgrind-checks.dsc b/src/test/tpkg/225-stub-only-valgrind-checks.tpkg/225-stub-only-valgrind-checks.dsc index d845ad44..7167a541 100644 --- a/src/test/tpkg/225-stub-only-valgrind-checks.tpkg/225-stub-only-valgrind-checks.dsc +++ b/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: