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 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 # 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/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/lib/ns/xfrout.c b/lib/ns/xfrout.c index e681004807..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; @@ -662,21 +673,22 @@ 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 */ 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 */ - 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 */ + struct xfr_stats stats; /*%< Transfer statistics */ } xfrout_ctx_t; static isc_result_t @@ -1180,11 +1192,11 @@ 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; xfr->verified_tsig = verified_tsig; - xfr->nmsg = 0; xfr->many_answers = many_answers; xfr->sends = 0; xfr->shuttingdown = false; @@ -1196,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 @@ -1344,7 +1361,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 +1393,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 @@ -1480,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; @@ -1534,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) { @@ -1618,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); @@ -1631,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); } diff --git a/util/copyrights b/util/copyrights index 88638c2c7c..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 @@ -1161,6 +1162,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