4522. [bug] Handle big gaps in log file version numbers better.

[RT #38688]

CHANGES

@@ -1,3 +1,6 @@
+4522.	[bug]		Handle big gaps in log file version numbers better.
+			[RT #38688]
+
 4521.	[cleanup]	Log it as an error if an entropy source is not
 			found and there is no fallback available. [RT #43659]
 

bin/tests/system/logfileconfig/clean.sh

@@ -20,3 +20,8 @@ rm -f ns1/query_log
 rm -f ns1/named_iso8601
 rm -f ns1/named_iso8601_utc
 rm -f ns1/rndc.out.test*
+rm -f ns1/dig.out.test*
+rm -f ns1/named_vers
+rm -f ns1/named_vers.*
+rm -f ns1/named_unlimited
+rm -f ns1/named_unlimited.*

bin/tests/system/logfileconfig/ns1/named.unlimited

@@ -0,0 +1,56 @@
+/*
+ * Copyright (C) 2016  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/.
+ */
+
+options {
+	query-source address 10.53.0.1;
+	notify-source 10.53.0.1;
+	transfer-source 10.53.0.1;
+	port 5300;
+	pid-file "named.pid";
+	listen-on port 5300 {
+		10.53.0.1;
+	};
+	listen-on-v6 { none; };
+	recursion no;
+	notify yes;
+};
+
+logging {
+	channel default_log {
+	  buffered no;
+	  file "named_unlimited" versions unlimited size 1000;
+	  severity debug 100;
+	  print-time yes;
+	};
+	category default { default_log; default_debug; };
+	category lame-servers { null; };
+
+	channel query_log {
+	  file "query_log";
+	  print-time yes;
+	  buffered yes;
+	};
+	category queries { query_log; };
+};
+
+controls {
+    inet 127.0.0.1 port 9593 allow {
+			 127.0.0.1/32; ::1/128; }
+			 keys { "rndc-key"; };
+};
+
+key "rndc-key" {
+	algorithm hmac-sha256;
+	secret "Am9vCg==";
+};
+
+
+zone "." {
+	type master;
+	file "root.db";
+};

bin/tests/system/logfileconfig/ns1/named.versconf

@@ -0,0 +1,56 @@
+/*
+ * Copyright (C) 2016  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/.
+ */
+
+options {
+	query-source address 10.53.0.1;
+	notify-source 10.53.0.1;
+	transfer-source 10.53.0.1;
+	port 5300;
+	pid-file "named.pid";
+	listen-on port 5300 {
+		10.53.0.1;
+	};
+	listen-on-v6 { none; };
+	recursion no;
+	notify yes;
+};
+
+logging {
+	channel default_log {
+	  buffered no;
+	  file "named_vers" versions 5 size 1000;	// really small size
+	  severity debug 100;
+	  print-time yes;
+	};
+	category default { default_log; default_debug; };
+	category lame-servers { null; };
+
+	channel query_log {
+	  file "query_log";
+	  print-time yes;
+	  buffered yes;
+	};
+	category queries { query_log; };
+};
+
+controls {
+    inet 127.0.0.1 port 9593 allow {
+			 127.0.0.1/32; ::1/128; }
+			 keys { "rndc-key"; };
+};
+
+key "rndc-key" {
+	algorithm hmac-sha256;
+	secret "Am9vCg==";
+};
+
+
+zone "." {
+	type master;
+	file "root.db";
+};

bin/tests/system/logfileconfig/tests.sh

@@ -18,6 +18,8 @@ SYMCONF="${THISDIR}/${CONFDIR}/named.symconf"
 PLAINCONF="${THISDIR}/${CONFDIR}/named.plainconf"
 ISOCONF="${THISDIR}/${CONFDIR}/named.iso8601"
 ISOCONFUTC="${THISDIR}/${CONFDIR}/named.iso8601-utc"
+VERSCONF="${THISDIR}/${CONFDIR}/named.versconf"
+UNLIMITEDCONF="${THISDIR}/${CONFDIR}/named.unlimited"
 PLAINFILE="named_log"
 DIRFILE="named_dir"
 PIPEFILE="named_pipe"
@@ -25,6 +27,8 @@ SYMFILE="named_sym"
 DLFILE="named_deflog"
 ISOFILE="named_iso8601"
 ISOUTCFILE="named_iso8601_utc"
+VERSFILE="named_vers"
+UNLIMITEDFILE="named_unlimited"
 PIDFILE="${THISDIR}/${CONFDIR}/named.pid"
 myRNDC="$RNDC -c ${THISDIR}/${CONFDIR}/rndc.conf"
 myNAMED="$NAMED -c ${THISDIR}/${CONFDIR}/named.conf -m record,size,mctx -T clienttest -T nosyslog -d 99 -X named.lock -U 4"
@@ -278,10 +282,10 @@ echo "I: testing iso8601 timestamp ($n)"
 cp $ISOCONF named.conf
 $myRNDC reconfig > rndc.out.test$n 2>&1
 if grep '^....-..-..T..:..:..\.... ' $ISOFILE > /dev/null; then
-        echo "I: testing iso8601 timestamp succeeded"
+	echo "I: testing iso8601 timestamp succeeded"
 else
-        echo "I: testing iso8601 timestamp failed"
+	echo "I: testing iso8601 timestamp failed"
-        status=`expr $status + 1`
+	status=`expr $status + 1`
 fi
 
 n=`expr $n + 1`
@@ -289,10 +293,77 @@ echo "I: testing iso8601-utc timestamp ($n)"
 cp $ISOCONFUTC named.conf
 $myRNDC reconfig > rndc.out.test$n 2>&1
 if grep '^....-..-..T..:..:..\....Z' $ISOUTCFILE > /dev/null; then
-        echo "I: testing iso8601-utc timestamp succeeded"
+	echo "I: testing iso8601-utc timestamp succeeded"
 else
-        echo "I: testing iso8601-utc timestamp failed"
+	echo "I: testing iso8601-utc timestamp failed"
-        status=`expr $status + 1`
+	status=`expr $status + 1`
+fi
+
+n=`expr $n + 1`
+echo "I: testing explict versions ($n)"
+cp $VERSCONF named.conf
+# a seconds since epoch version number
+touch $VERSFILE.1480039317
+t1=`$PERL -e 'print time()."\n";'`
+$myRNDC reconfig > rndc.out.test$n 2>&1
+$DIG version.bind txt ch @10.53.0.1 -p 5300 > dig.out.test$n
+t2=`$PERL -e 'print time()."\n";'`
+t=`expr ${t2:-0} - ${t1:-0}`
+if test ${t:-1000} -gt 1
+then
+	echo "I: testing explict versions failed cleanup of old entries took too long"
+	status=`expr $status + 1`
+fi 
+if ! grep "status: NOERROR" dig.out.test$n > /dev/null
+then
+	echo "I: testing explict versions failed DiG lookup failed"
+	status=`expr $status + 1`
+fi
+if test -f $VERSFILE.1480039317
+then
+	echo "I: testing explict versions failed $VERSFILE.1480039317 not removed"
+	status=`expr $status + 1`
+fi
+if test -f $VERSFILE.5
+then
+	echo "I: testing explict versions failed $VERSFILE.5 exists"
+	status=`expr $status + 1`
+fi
+if test ! -f $VERSFILE.4
+then
+	echo "I: testing explict versions failed $VERSFILE.4 does not exist"
+	status=`expr $status + 1`
+fi
+
+n=`expr $n + 1`
+echo "I: testing unlimited versions ($n)"
+cp $UNLIMITEDCONF named.conf
+# a seconds since epoch version number
+touch $UNLIMITEDFILE.1480039317
+t1=`$PERL -e 'print time()."\n";'`
+$myRNDC reconfig > rndc.out.test$n 2>&1
+$DIG version.bind txt ch @10.53.0.1 -p 5300 > dig.out.test$n
+t2=`$PERL -e 'print time()."\n";'`
+t=`expr ${t2:-0} - ${t1:-0}`
+if test ${t:-1000} -gt 1
+then
+	echo "I: testing unlimited versions failed took too long"
+	status=`expr $status + 1`
+fi 
+if ! grep "status: NOERROR" dig.out.test$n > /dev/null
+then
+	echo "I: testing unlimited versions failed DiG lookup failed"
+	status=`expr $status + 1`
+fi
+if test ! -f $UNLIMITEDFILE.1480039317
+then
+	echo "I: testing unlimited versions failed $UNLIMITEDFILE.1480039317 removed"
+	status=`expr $status + 1`
+fi
+if test ! -f $UNLIMITEDFILE.5
+then
+	echo "I: testing unlimited versions failed $UNLIMITEDFILE.5 does not"
+	status=`expr $status + 1`
 fi
 
 echo "I:exit status: $status"

lib/isc/log.c

@@ -223,7 +223,7 @@ static isc_result_t
 sync_channellist(isc_logconfig_t *lcfg);
 
 static isc_result_t
-greatest_version(isc_logfile_t *file, int *greatest);
+greatest_version(isc_logfile_t *file, int versions, int *greatest);
 
 static void
 isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category,
@@ -1132,7 +1132,7 @@ sync_channellist(isc_logconfig_t *lcfg) {
 }
 
 static isc_result_t
-greatest_version(isc_logfile_t *file, int *greatestp) {
+greatest_version(isc_logfile_t *file, int versions, int *greatestp) {
 	char *bname, *digit_end;
 	const char *dirname;
 	int version, greatest = -1;
@@ -1188,13 +1188,24 @@ greatest_version(isc_logfile_t *file, int *greatestp) {
 		{
 			version = strtol(&dir.entry.name[bnamelen + 1],
 					 &digit_end, 10);
-			if (*digit_end == '\0' && version > greatest)
+			/*
+			 * Remove any backup files that exceed versions.
+			 */
+			if (*digit_end == '\0' && version >= versions) {
+				result = isc_file_remove(dir.entry.name);
+				if (result != ISC_R_SUCCESS &&
+				    result != ISC_R_FILENOTFOUND)
+					syslog(LOG_ERR, "unable to remove "
+					       "log file '%s': %s",
+					       dir.entry.name,
+					       isc_result_totext(result));
+			} else if (*digit_end == '\0' && version > greatest)
 				greatest = version;
 		}
 	}
 	isc_dir_close(&dir);
 
-	*greatestp = ++greatest;
+	*greatestp = greatest;
 
 	return (ISC_R_SUCCESS);
 }
@@ -1219,56 +1230,41 @@ isc_logfile_roll(isc_logfile_t *file) {
 
 	path = file->name;
 
-	/*
+	if (file->versions == ISC_LOG_ROLLINFINITE) {
-	 * Set greatest_version to the greatest existing version
-	 * (not the maximum requested version).  This is 1 based even
-	 * though the file names are 0 based, so an oldest log of log.1
-	 * is a greatest_version of 2.
-	 */
-	result = greatest_version(file, &greatest);
-	if (result != ISC_R_SUCCESS)
-		return (result);
-
-	/*
-	 * Now greatest should be set to the highest version number desired.
-	 * Since the highest number is one less than file->versions.
-	 * when not doing infinite log rolling, greatest will need to be
-	 * decremented when it is equal to -- or greater than --
-	 * file->versions.  When greatest is less than
-	 * file->versions, it is already suitable for use as
-	 * the maximum version number.
-	 */
-
-	if (file->versions == ISC_LOG_ROLLINFINITE || file->versions > greatest)
-		;		/* Do nothing. */
-	else
 		/*
-		 * When greatest is >= file->versions, it needs to
+		 * Find the first missing entry in the log file sequence.
-		 * be reduced until it is file->versions - 1.
-		 * Remove any excess logs on the way to that value.
 		 */
-		while (--greatest >= file->versions) {
+		for (greatest = 0; greatest < INT_MAX; greatest++) {
-			n = snprintf(current, sizeof(current), "%s.%d",
+			n = snprintf(current, sizeof(current),
-				     path, greatest);
+				     "%s.%u", path, greatest) ;
 			if (n >= (int)sizeof(current) || n < 0)
-				result = ISC_R_NOSPACE;
+				break;
-			else
+			if (!isc_file_exists(current))
-				result = isc_file_remove(current);
+				break;
-			if (result != ISC_R_SUCCESS &&
-			    result != ISC_R_FILENOTFOUND)
-				syslog(LOG_ERR,
-				       "unable to remove log file '%s.%d': %s",
-				       path, greatest,
-				       isc_result_totext(result));
 		}
+	} else {
+		/*
+		 * Get the largest existing version and remove any
+		 * version greater than the permitted version.
+		 */
+		result = greatest_version(file, file->versions, &greatest);
+		if (result != ISC_R_SUCCESS)
+			return (result);
+
+		/*
+		 * Increment if greatest is not the actual maximum value.
+		 */
+		if (greatest < file->versions - 1)
+			greatest++;
+	}
 
 	for (i = greatest; i > 0; i--) {
 		result = ISC_R_SUCCESS;
-		n = snprintf(current, sizeof(current), "%s.%d", path, i - 1);
+		n = snprintf(current, sizeof(current), "%s.%u", path, i - 1);
 		if (n >= (int)sizeof(current) || n < 0)
 			result = ISC_R_NOSPACE;
 		if (result == ISC_R_SUCCESS) {
-			n = snprintf(new, sizeof(new), "%s.%d", path, i);
+			n = snprintf(new, sizeof(new), "%s.%u", path, i);
 			if (n >= (int)sizeof(new) || n < 0)
 				result = ISC_R_NOSPACE;
 		}
@@ -1277,8 +1273,8 @@ isc_logfile_roll(isc_logfile_t *file) {
 		if (result != ISC_R_SUCCESS &&
 		    result != ISC_R_FILENOTFOUND)
 			syslog(LOG_ERR,
-			       "unable to rename log file '%s.%d' to "
+			       "unable to rename log file '%s.%u' to "
-			       "'%s.%d': %s", path, i - 1, path, i,
+			       "'%s.%u': %s", path, i - 1, path, i,
 			       isc_result_totext(result));
 	}
 

util/copyrights

@@ -1717,6 +1717,7 @@
 ./bin/tests/system/logfileconfig/ns1/named.plain	CONF-C	2011,2013,2014,2016
 ./bin/tests/system/logfileconfig/ns1/named.plainconf	CONF-C	2014,2016
 ./bin/tests/system/logfileconfig/ns1/named.symconf	CONF-C	2011,2013,2016
+./bin/tests/system/logfileconfig/ns1/named.versconf	CONF-C	2016
 ./bin/tests/system/logfileconfig/ns1/rndc.conf	CONF-C	2011,2013,2016
 ./bin/tests/system/logfileconfig/ns1/root.db	ZONE	2011,2016
 ./bin/tests/system/logfileconfig/setup.sh	SH	2011,2012,2014,2016