From c20d81fd0679cb3fee53c91e0757d973842f7869 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 31 Jan 2019 15:43:58 +0100 Subject: [PATCH 1/6] Track QUESTION section presence using a boolean The 'nmsg' field of the xfrout_ctx_t structure is an integer, even though it is only ever compared against 0 (for tracking whether the QUESTION section has already been sent to the client). Use a boolean instead as it is more appropriate and also enables 'nmsg' to be repurposed. --- lib/ns/xfrout.c | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/lib/ns/xfrout.c b/lib/ns/xfrout.c index e681004807..0212887e91 100644 --- a/lib/ns/xfrout.c +++ b/lib/ns/xfrout.c @@ -662,7 +662,8 @@ typedef struct { dns_dbversion_t *ver; isc_quota_t *quota; rrstream_t *stream; /* The XFR RR stream */ - bool end_of_stream; /* EOS has been reached */ + bool question_added; /* QUESTION section sent? */ + bool end_of_stream; /* EOS has been reached */ isc_buffer_t buf; /* Buffer for message owner names and rdatas */ isc_buffer_t txlenbuf; /* Transmit length buffer */ @@ -672,10 +673,10 @@ typedef struct { unsigned int nmsg; /* Number of messages sent */ dns_tsigkey_t *tsigkey; /* Key used to create TSIG */ isc_buffer_t *lasttsig; /* the last TSIG */ - bool verified_tsig; /* verified request MAC */ - bool many_answers; + bool verified_tsig; /* verified request MAC */ + bool many_answers; int sends; /* Send in progress */ - bool shuttingdown; + bool shuttingdown; const char *mnemonic; /* Style of transfer */ } xfrout_ctx_t; @@ -1180,6 +1181,7 @@ xfrout_ctx_create(isc_mem_t *mctx, ns_client_t *client, unsigned int id, dns_zone_attach(zone, &xfr->zone); dns_db_attach(db, &xfr->db); dns_db_attachversion(db, ver, &xfr->ver); + xfr->question_added = false; xfr->end_of_stream = false; xfr->tsigkey = tsigkey; xfr->lasttsig = lasttsig; @@ -1344,7 +1346,7 @@ sendstream(xfrout_ctx_t *xfr) { * BIND 8.2.1 will not recognize an IXFR if it does not * have a question section. */ - if (xfr->nmsg == 0) { + if (!xfr->question_added) { dns_name_t *qname = NULL; isc_region_t r; @@ -1376,6 +1378,7 @@ sendstream(xfrout_ctx_t *xfr) { ISC_LIST_APPEND(qname->list, qrdataset, link); dns_message_addname(msg, qname, DNS_SECTION_QUESTION); + xfr->question_added = true; } else { /* * Reserve space for the 12-byte message header From 7f52b872276a8624988a67701939869037a035cd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 31 Jan 2019 15:43:58 +0100 Subject: [PATCH 2/6] Maintain and report outgoing transfer statistics Transfer statistics are currently only reported for incoming transfers, even though they are equally useful for outgoing transfers. Define a separate structure for keeping track of the number of messages, records, and bytes sent during each outgoing transfer, along with the time each outgoing transfer took. Repurpose the 'nmsg' field of the xfrout_ctx_t structure for tracking the number of messages actually sent, ensuring it is only increased after isc_socket_send() indicates success. Report the statistics gathered when an outgoing transfer completes. --- lib/ns/xfrout.c | 61 ++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 53 insertions(+), 8 deletions(-) diff --git a/lib/ns/xfrout.c b/lib/ns/xfrout.c index 0212887e91..f98ab6b7f5 100644 --- a/lib/ns/xfrout.c +++ b/lib/ns/xfrout.c @@ -645,11 +645,22 @@ static rrstream_methods_t compound_rrstream_methods = { }; /**************************************************************************/ -/* + +/*% + * Structure holding outgoing transfer statistics + */ +struct xfr_stats { + uint64_t nmsg; /*%< Number of messages sent */ + uint64_t nrecs; /*%< Number of records sent */ + uint64_t nbytes; /*%< Number of bytes sent */ + isc_time_t start; /*%< Start time of the transfer */ + isc_time_t end; /*%< End time of the transfer */ +}; + +/*% * An 'xfrout_ctx_t' contains the state of an outgoing AXFR or IXFR * in progress. */ - typedef struct { isc_mem_t *mctx; ns_client_t *client; @@ -670,7 +681,6 @@ typedef struct { isc_buffer_t txbuf; /* Transmit message buffer */ void *txmem; unsigned int txmemlen; - unsigned int nmsg; /* Number of messages sent */ dns_tsigkey_t *tsigkey; /* Key used to create TSIG */ isc_buffer_t *lasttsig; /* the last TSIG */ bool verified_tsig; /* verified request MAC */ @@ -678,6 +688,7 @@ typedef struct { int sends; /* Send in progress */ bool shuttingdown; const char *mnemonic; /* Style of transfer */ + struct xfr_stats stats; /*%< Transfer statistics */ } xfrout_ctx_t; static isc_result_t @@ -1186,7 +1197,6 @@ xfrout_ctx_create(isc_mem_t *mctx, ns_client_t *client, unsigned int id, xfr->tsigkey = tsigkey; xfr->lasttsig = lasttsig; xfr->verified_tsig = verified_tsig; - xfr->nmsg = 0; xfr->many_answers = many_answers; xfr->sends = 0; xfr->shuttingdown = false; @@ -1198,6 +1208,11 @@ xfrout_ctx_create(isc_mem_t *mctx, ns_client_t *client, unsigned int id, xfr->stream = NULL; xfr->quota = NULL; + xfr->stats.nmsg = 0; + xfr->stats.nrecs = 0; + xfr->stats.nbytes = 0; + isc_time_now(&xfr->stats.start); + /* * Allocate a temporary buffer for the uncompressed response * message data. The size should be no more than 65535 bytes @@ -1483,6 +1498,8 @@ sendstream(xfrout_ctx_t *xfr) { dns_message_addname(msg, msgname, DNS_SECTION_ANSWER); msgname = NULL; + xfr->stats.nrecs++; + result = xfr->stream->methods->next(xfr->stream); if (result == ISC_R_NOMORE) { xfr->end_of_stream = true; @@ -1537,8 +1554,6 @@ sendstream(xfrout_ctx_t *xfr) { /* Advance lasttsig to be the last TSIG generated */ CHECK(dns_message_getquerytsig(msg, xfr->mctx, &xfr->lasttsig)); - xfr->nmsg++; - failure: if (msgname != NULL) { if (msgrds != NULL) { @@ -1621,10 +1636,20 @@ xfrout_senddone(isc_task_t *task, isc_event_t *event) { INSIST(event->ev_type == ISC_SOCKEVENT_SENDDONE); - isc_event_free(&event); xfr->sends--; INSIST(xfr->sends == 0); + /* + * Update transfer statistics if sending succeeded, accounting for the + * two-byte TCP length prefix included in the number of bytes sent. + */ + if (evresult == ISC_R_SUCCESS) { + xfr->stats.nmsg++; + xfr->stats.nbytes += sev->region.length - 2; + } + + isc_event_free(&event); + (void)isc_timer_touch(xfr->client->timer); if (xfr->shuttingdown == true) { xfrout_maybe_destroy(xfr); @@ -1634,8 +1659,28 @@ xfrout_senddone(isc_task_t *task, isc_event_t *event) { sendstream(xfr); } else { /* End of zone transfer stream. */ + uint64_t msecs, persec; + inc_stats(xfr->client, xfr->zone, ns_statscounter_xfrdone); - xfrout_log(xfr, ISC_LOG_INFO, "%s ended", xfr->mnemonic); + isc_time_now(&xfr->stats.end); + msecs = isc_time_microdiff(&xfr->stats.end, &xfr->stats.start); + msecs /= 1000; + if (msecs == 0) { + msecs = 1; + } + persec = (xfr->stats.nbytes * 1000) / msecs; + xfrout_log(xfr, ISC_LOG_INFO, + "%s ended: " + "%" PRIu64 " messages, %" PRIu64 " records, " + "%" PRIu64 " bytes, " + "%u.%03u secs (%u bytes/sec)", + xfr->mnemonic, + xfr->stats.nmsg, xfr->stats.nrecs, + xfr->stats.nbytes, + (unsigned int) (msecs / 1000), + (unsigned int) (msecs % 1000), + (unsigned int) persec); + ns_client_next(xfr->client, ISC_R_SUCCESS); xfrout_ctx_destroy(&xfr); } From 6071c6cc279b746a9e0b8853d4f8936f209f12c6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 31 Jan 2019 15:43:58 +0100 Subject: [PATCH 3/6] Add functions for extracting transfer statistics Add two helper shell functions to facilitate extracting transfer statistics from dig output and named log files. --- bin/tests/system/conf.sh.common | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/bin/tests/system/conf.sh.common b/bin/tests/system/conf.sh.common index a09968802f..3304053b9b 100644 --- a/bin/tests/system/conf.sh.common +++ b/bin/tests/system/conf.sh.common @@ -260,6 +260,27 @@ rndc_reconfig() { done } +# get_dig_xfer_stats: extract transfer statistics from dig output stored +# in $1, converting them to a format used by some system tests. +get_dig_xfer_stats() { + LOGFILE="$1" + echo "messages=`sed -n "s/^;; XFR size: .*messages \([0-9][0-9]*\).*/\1/p" "${LOGFILE}"`" + echo "records=`sed -n "s/^;; XFR size: \([0-9][0-9]*\) records.*/\1/p" "${LOGFILE}"`" + echo "bytes=`sed -n "s/^;; XFR size: .*bytes \([0-9][0-9]*\).*/\1/p" "${LOGFILE}"`" +} + +# get_named_xfer_stats: from named log file $1, extract transfer +# statistics for the last transfer for peer $2 and zone $3, converting +# them to a format used by some system tests. +get_named_xfer_stats() { + LOGFILE="$1" + PEER="$2" + ZONE="$3" + echo "messages=`grep "${PEER}" "${LOGFILE}" | sed -n "s/.*${ZONE}.* \([0-9][0-9]*\) messages.*/\1/p" | tail -1`" + echo "records=`grep "${PEER}" "${LOGFILE}" | sed -n "s/.*${ZONE}.* \([0-9][0-9]*\) records.*/\1/p" | tail -1`" + echo "bytes=`grep "${PEER}" "${LOGFILE}" | sed -n "s/.*${ZONE}.* \([0-9][0-9]*\) bytes.*/\1/p" | tail -1`" +} + # # Export command paths # From a22e24a411c18099171d4f6a2abca59dd21182f3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 31 Jan 2019 15:43:58 +0100 Subject: [PATCH 4/6] Add system tests for AXFR statistics Ensure AXFR statistics are calculated correctly by dig and named, both for incoming and outgoing transfers. Rather than employing a zone which is already used in the "xfer" system test, create a new one whose AXFR form spans multiple TCP messages. Disable EDNS when using dig to request an AXFR so that the same reference file can be used for testing statistics calculated by both dig and named (dig uses EDNS by default when sending transfer requests, which affects the number of bytes transferred). --- bin/tests/system/xfer/axfr-stats.good | 3 ++ bin/tests/system/xfer/clean.sh | 3 +- bin/tests/system/xfer/ns1/named.conf.in | 5 +++ bin/tests/system/xfer/ns1/xfer-stats.db | 13 ++++++++ bin/tests/system/xfer/ns3/named.conf.in | 6 ++++ bin/tests/system/xfer/tests.sh | 44 +++++++++++++++++++++++++ util/copyrights | 1 + 7 files changed, 74 insertions(+), 1 deletion(-) create mode 100644 bin/tests/system/xfer/axfr-stats.good create mode 100644 bin/tests/system/xfer/ns1/xfer-stats.db diff --git a/bin/tests/system/xfer/axfr-stats.good b/bin/tests/system/xfer/axfr-stats.good new file mode 100644 index 0000000000..264af09705 --- /dev/null +++ b/bin/tests/system/xfer/axfr-stats.good @@ -0,0 +1,3 @@ +messages=16 +records=10003 +bytes=218227 diff --git a/bin/tests/system/xfer/clean.sh b/bin/tests/system/xfer/clean.sh index 10ff41a84f..d5843e5dae 100644 --- a/bin/tests/system/xfer/clean.sh +++ b/bin/tests/system/xfer/clean.sh @@ -15,10 +15,11 @@ rm -f dig.out.* rm -f axfr.out +rm -f stats.* rm -f ns1/slave.db ns2/slave.db rm -f ns1/edns-expire.db rm -f ns2/example.db ns2/tsigzone.db ns2/example.db.jnl -rm -f ns3/example.bk ns3/tsigzone.bk ns3/example.bk.jnl +rm -f ns3/example.bk ns3/xfer-stats.bk ns3/tsigzone.bk ns3/example.bk.jnl rm -f ns3/master.bk ns3/master.bk.jnl rm -f ns4/nil.db ns4/root.db rm -f ns6/*.db ns6/*.bk ns6/*.jnl diff --git a/bin/tests/system/xfer/ns1/named.conf.in b/bin/tests/system/xfer/ns1/named.conf.in index c0e8112ec6..f665f728e5 100644 --- a/bin/tests/system/xfer/ns1/named.conf.in +++ b/bin/tests/system/xfer/ns1/named.conf.in @@ -52,3 +52,8 @@ zone "ixfr-too-big" { allow-update { any; }; file "ixfr-too-big.db"; }; + +zone "xfer-stats" { + type master; + file "xfer-stats.db"; +}; diff --git a/bin/tests/system/xfer/ns1/xfer-stats.db b/bin/tests/system/xfer/ns1/xfer-stats.db new file mode 100644 index 0000000000..c57b786620 --- /dev/null +++ b/bin/tests/system/xfer/ns1/xfer-stats.db @@ -0,0 +1,13 @@ +; Copyright (C) Internet Systems Consortium, Inc. ("ISC") +; +; This Source Code Form is subject to the terms of the Mozilla Public +; License, v. 2.0. If a copy of the MPL was not distributed with this +; file, You can obtain one at http://mozilla.org/MPL/2.0/. +; +; See the COPYRIGHT file distributed with this work for additional +; information regarding copyright ownership. + +$TTL 3600 +@ SOA . . 0 0 0 0 0 +@ NS . +$GENERATE 1-10000 $ TXT $ diff --git a/bin/tests/system/xfer/ns3/named.conf.in b/bin/tests/system/xfer/ns3/named.conf.in index b4bfac519e..7e8955dce3 100644 --- a/bin/tests/system/xfer/ns3/named.conf.in +++ b/bin/tests/system/xfer/ns3/named.conf.in @@ -69,3 +69,9 @@ zone "mapped" { masterfile-format map; file "mapped.bk"; }; + +zone "xfer-stats" { + type slave; + masters { 10.53.0.1; }; + file "xfer-stats.bk"; +}; diff --git a/bin/tests/system/xfer/tests.sh b/bin/tests/system/xfer/tests.sh index d9286c4016..dcd4d06ce5 100755 --- a/bin/tests/system/xfer/tests.sh +++ b/bin/tests/system/xfer/tests.sh @@ -464,5 +464,49 @@ grep "'ixfr-too-big/IN'.*: too many records" ns6/named.run >/dev/null || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi status=`expr $status + $tmp` +n=`expr $n + 1` +echo_i "checking whether dig calculates AXFR statistics correctly" +# Loop until the secondary server manages to transfer the "xfer-stats" zone so +# that we can both check dig output and immediately proceed with the next test. +# Use -b so that we can discern between incoming and outgoing transfers in ns3 +# logs later on. +tmp=1 +for i in 1 2 3 4 5 6 7 8 9 10; do + $DIG $DIGOPTS +noedns +stat -b 10.53.0.2 @10.53.0.3 xfer-stats. AXFR > dig.out.ns3.$n + if grep "; Transfer failed" dig.out.ns3.$n > /dev/null; then + sleep 1 + else + tmp=0 + break + fi +done +if [ $tmp -ne 0 ]; then + echo_i "timed out waiting for zone transfer" +else + get_dig_xfer_stats dig.out.ns3.$n > stats.dig + diff axfr-stats.good stats.dig || tmp=1 +fi +if test $tmp != 0 ; then echo_i "failed"; fi +status=`expr $status + $tmp` + +# Note: in the next two tests, we use ns3 logs for checking both incoming and +# outgoing transfer statistics as ns3 is both a secondary server (for ns1) and a +# primary server (for dig queries from the previous test) for "xfer-stats". +n=`expr $n + 1` +echo_i "checking whether named calculates incoming AXFR statistics correctly" +tmp=0 +get_named_xfer_stats ns3/named.run 10.53.0.1 xfer-stats "Transfer completed" > stats.incoming +diff axfr-stats.good stats.incoming || tmp=1 +if test $tmp != 0 ; then echo_i "failed"; fi +status=`expr $status + $tmp` + +n=`expr $n + 1` +echo_i "checking whether named calculates outgoing AXFR statistics correctly" +tmp=0 +get_named_xfer_stats ns3/named.run 10.53.0.2 xfer-stats "AXFR ended" > stats.outgoing +diff axfr-stats.good stats.outgoing || tmp=1 +if test $tmp != 0 ; then echo_i "failed"; fi +status=`expr $status + $tmp` + echo_i "exit status: $status" [ $status -eq 0 ] || exit 1 diff --git a/util/copyrights b/util/copyrights index 88638c2c7c..1881953c18 100644 --- a/util/copyrights +++ b/util/copyrights @@ -1161,6 +1161,7 @@ ./bin/tests/system/xfer/ans5/unknownkey X 2011,2018,2019 ./bin/tests/system/xfer/ans5/unsigned X 2011,2018,2019 ./bin/tests/system/xfer/ans5/wrongkey X 2011,2018,2019 +./bin/tests/system/xfer/axfr-stats.good X 2019 ./bin/tests/system/xfer/clean.sh SH 2000,2001,2004,2007,2011,2012,2013,2014,2015,2016,2018,2019 ./bin/tests/system/xfer/dig1.good X 2000,2001,2003,2004,2009,2011,2012,2013,2014,2015,2016,2017,2018,2019 ./bin/tests/system/xfer/dig2.good X 2000,2001,2003,2004,2009,2011,2012,2013,2014,2015,2016,2017,2018,2019 From a9a47c79e93ef7c91e99a7b1e60cc306abbc85c5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 31 Jan 2019 15:43:58 +0100 Subject: [PATCH 5/6] Add system tests for IXFR statistics Ensure IXFR statistics are calculated correctly by dig and named, both for incoming and outgoing transfers. Disable EDNS when using dig to request an IXFR so that the same reference file can be used for testing statistics calculated by both dig and named (dig uses EDNS by default when sending transfer requests, which affects the number of bytes transferred). --- bin/tests/system/ixfr/clean.sh | 3 ++- bin/tests/system/ixfr/ixfr-stats.good | 3 +++ bin/tests/system/ixfr/tests.sh | 25 +++++++++++++++++++++++++ util/copyrights | 1 + 4 files changed, 31 insertions(+), 1 deletion(-) create mode 100644 bin/tests/system/ixfr/ixfr-stats.good diff --git a/bin/tests/system/ixfr/clean.sh b/bin/tests/system/ixfr/clean.sh index d75c36e4eb..fe05b404de 100644 --- a/bin/tests/system/ixfr/clean.sh +++ b/bin/tests/system/ixfr/clean.sh @@ -9,6 +9,7 @@ # See the COPYRIGHT file distributed with this work for additional # information regarding copyright ownership. +rm -f stats.* rm -f ns1/myftp.db rm -f ns3/*.jnl ns3/mytest.db ns3/subtest.db rm -f ns4/*.jnl ns4/*.db @@ -19,4 +20,4 @@ rm -f */ans.run rm -f dig.out dig.out1 dig.out2 dig.out3 rm -f ns3/large.db rm -f ns*/named.lock -rm -f ns*/managed-keys.bind* +rm -f ns*/managed-keys.bind* ns*/*.mkeys diff --git a/bin/tests/system/ixfr/ixfr-stats.good b/bin/tests/system/ixfr/ixfr-stats.good new file mode 100644 index 0000000000..dd62e121d6 --- /dev/null +++ b/bin/tests/system/ixfr/ixfr-stats.good @@ -0,0 +1,3 @@ +messages=1 +records=6 +bytes=219 diff --git a/bin/tests/system/ixfr/tests.sh b/bin/tests/system/ixfr/tests.sh index d023eef302..64d11a8529 100644 --- a/bin/tests/system/ixfr/tests.sh +++ b/bin/tests/system/ixfr/tests.sh @@ -307,5 +307,30 @@ if [ ${ret} != 0 ]; then status=1; fi +echo_i "checking whether dig calculates IXFR statistics correctly" +ret=0 +$DIG $DIGOPTS +noedns +stat -b 10.53.0.4 @10.53.0.4 test. ixfr=2 > dig.out1 +get_dig_xfer_stats dig.out1 > stats.dig +diff ixfr-stats.good stats.dig || ret=1 +if [ $ret != 0 ]; then echo_i "failed"; fi +status=`expr $status + $ret` + +# Note: in the next two tests, we use ns4 logs for checking both incoming and +# outgoing transfer statistics as ns4 is both a secondary server (for ns3) and a +# primary server (for dig queries from the previous test) for "test". +echo_i "checking whether named calculates incoming IXFR statistics correctly" +ret=0 +get_named_xfer_stats ns4/named.run 10.53.0.3 test "Transfer completed" > stats.incoming +diff ixfr-stats.good stats.incoming || ret=1 +if [ $ret != 0 ]; then echo_i "failed"; fi +status=`expr $status + $ret` + +echo_i "checking whether named calculates outgoing IXFR statistics correctly" +ret=0 +get_named_xfer_stats ns4/named.run 10.53.0.4 test "IXFR ended" > stats.outgoing +diff ixfr-stats.good stats.outgoing || ret=1 +if [ $ret != 0 ]; then echo_i "failed"; fi +status=`expr $status + $ret` + echo_i "exit status: $status" [ $status -eq 0 ] || exit 1 diff --git a/util/copyrights b/util/copyrights index 1881953c18..a9ac4f82a4 100644 --- a/util/copyrights +++ b/util/copyrights @@ -702,6 +702,7 @@ ./bin/tests/system/integrity/tests.sh SH 2017,2018,2019 ./bin/tests/system/ixfr/ans2/startme X 2011,2018,2019 ./bin/tests/system/ixfr/clean.sh SH 2001,2004,2007,2011,2012,2014,2015,2016,2018,2019 +./bin/tests/system/ixfr/ixfr-stats.good X 2019 ./bin/tests/system/ixfr/ns1/startme X 2012,2013,2018,2019 ./bin/tests/system/ixfr/prereq.sh SH 2001,2004,2007,2012,2014,2016,2018,2019 ./bin/tests/system/ixfr/setup.sh SH 2001,2004,2007,2011,2012,2013,2014,2016,2018,2019 From ed6317a1bef9043547caaee113b10cda166642b0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20K=C4=99pie=C5=84?= Date: Thu, 31 Jan 2019 15:43:58 +0100 Subject: [PATCH 6/6] Add CHANGES entry 5153. [func] Zone transfer statistics (size, number of records, and number of messages) are now logged for outgoing transfers as well as incoming ones. [GL #513] --- CHANGES | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/CHANGES b/CHANGES index 83846d3877..73db27e932 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,7 @@ +5153. [func] Zone transfer statistics (size, number of records, and + number of messages) are now logged for outgoing + transfers as well as incoming ones. [GL #513] + 5152. [func] Improved logging of DNSSEC key events: - Zone signing and DNSKEY maintenance events are now logged to the "dnssec" category