Merge branch '513-add-xfer-stats-for-primary-servers' into 'master'

Make primary's transfer log more detailed

See merge request isc-projects/bind9!1427

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

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
 #

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

bin/tests/system/ixfr/ixfr-stats.good

@@ -0,0 +1,3 @@
+messages=1
+records=6
+bytes=219

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

bin/tests/system/xfer/axfr-stats.good

@@ -0,0 +1,3 @@
+messages=16
+records=10003
+bytes=218227

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

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";
+};

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	$

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";
+};

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

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);
 	}

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