Merge branch '1675-logfileconfig-system-test-crashes-occasionally-rwlock-v9_16' into 'v9_16'

Use isc_rwlock to lock .logconfig member of isc_log_t See merge request isc-projects/bind9!3256
2020-03-18 12:48:13 +00:00
parent 072dacfc30 11a6ac594a
commit 2de447b088
1 changed files with 70 additions and 49 deletions
--- a/lib/isc/log.c
+++ b/lib/isc/log.c
@@ -19,6 +19,7 @@
 #include <sys/types.h> /* dev_t FreeBSD 2.1 */
 #include <time.h>

+#include <isc/atomic.h>
 #include <isc/dir.h>
 #include <isc/file.h>
 #include <isc/log.h>
@@ -26,6 +27,7 @@
 #include <isc/mem.h>
 #include <isc/platform.h>
 #include <isc/print.h>
+#include <isc/rwlock.h>
 #include <isc/stat.h>
 #include <isc/stdio.h>
 #include <isc/string.h>
@@ -38,6 +40,11 @@
 #define LCFG_MAGIC	   ISC_MAGIC('L', 'c', 'f', 'g')
 #define VALID_CONFIG(lcfg) ISC_MAGIC_VALID(lcfg, LCFG_MAGIC)

+#define RDLOCK(lp)   RWLOCK(lp, isc_rwlocktype_read);
+#define WRLOCK(lp)   RWLOCK(lp, isc_rwlocktype_write);
+#define RDUNLOCK(lp) RWUNLOCK(lp, isc_rwlocktype_read);
+#define WRUNLOCK(lp) RWUNLOCK(lp, isc_rwlocktype_write);
+
 /*
 * XXXDCL make dynamic?
 */
@@ -136,9 +143,11 @@ struct isc_log {
 	isc_logmodule_t *modules;
 	unsigned int module_count;
 	int debug_level;
+	isc_rwlock_t lcfg_rwl;
+	/* Locked by isc_log lcfg_rwl */
+	isc_logconfig_t *logconfig;
 	isc_mutex_t lock;
 	/* Locked by isc_log lock. */
-	isc_logconfig_t *logconfig;
 	char buffer[LOG_BUFFER_SIZE];
 	ISC_LIST(isc_logmessage_t) messages;
 };
@@ -252,6 +261,7 @@ isc_log_create(isc_mem_t *mctx, isc_log_t **lctxp, isc_logconfig_t **lcfgp) {
 	ISC_LIST_INIT(lctx->messages);

 	isc_mutex_init(&lctx->lock);
+	isc_rwlock_init(&lctx->lcfg_rwl, 0, 0);

 	/*
 	 * Normally setting the magic number is the last step done
@@ -349,12 +359,10 @@ isc_logconfig_use(isc_log_t *lctx, isc_logconfig_t *lcfg) {
 	 */
 	sync_channellist(lcfg);

-	LOCK(&lctx->lock);
-
+	WRLOCK(&lctx->lcfg_rwl);
 	old_cfg = lctx->logconfig;
 	lctx->logconfig = lcfg;
-
-	UNLOCK(&lctx->lock);
+	WRUNLOCK(&lctx->lcfg_rwl);

 	isc_logconfig_destroy(&old_cfg);
 }
@@ -372,12 +380,16 @@ isc_log_destroy(isc_log_t **lctxp) {
 	*lctxp = NULL;
 	mctx = lctx->mctx;

-	if (lctx->logconfig != NULL) {
-		lcfg = lctx->logconfig;
-		lctx->logconfig = NULL;
+	WRLOCK(&lctx->lcfg_rwl);
+	lcfg = lctx->logconfig;
+	lctx->logconfig = NULL;
+	WRUNLOCK(&lctx->lcfg_rwl);
+
+	if (lcfg != NULL) {
 		isc_logconfig_destroy(&lcfg);
 	}

+	isc_rwlock_destroy(&lctx->lcfg_rwl);
 	isc_mutex_destroy(&lctx->lock);

 	while ((message = ISC_LIST_HEAD(lctx->messages)) != NULL) {
@@ -404,7 +416,6 @@ isc_logconfig_destroy(isc_logconfig_t **lcfgp) {
 	isc_logconfig_t *lcfg;
 	isc_mem_t *mctx;
 	isc_logchannel_t *channel;
-	isc_logchannellist_t *item;
 	char *filename;
 	unsigned int i;

@@ -417,7 +428,11 @@ isc_logconfig_destroy(isc_logconfig_t **lcfgp) {
 	 * This function cannot be called with a logconfig that is in
 	 * use by a log context.
 	 */
-	REQUIRE(lcfg->lctx != NULL && lcfg->lctx->logconfig != lcfg);
+	REQUIRE(lcfg->lctx != NULL);
+
+	RDLOCK(&lcfg->lctx->lcfg_rwl);
+	REQUIRE(lcfg->lctx->logconfig != lcfg);
+	RDUNLOCK(&lcfg->lctx->lcfg_rwl);

 	mctx = lcfg->lctx->mctx;

@@ -444,6 +459,7 @@ isc_logconfig_destroy(isc_logconfig_t **lcfgp) {
 	}

 	for (i = 0; i < lcfg->channellist_count; i++) {
+		isc_logchannellist_t *item;
 		while ((item = ISC_LIST_HEAD(lcfg->channellists[i])) != NULL) {
 			ISC_LIST_UNLINK(lcfg->channellists[i], item, link);
 			isc_mem_put(mctx, item, sizeof(*item));
@@ -675,6 +691,7 @@ isc_log_createchannel(isc_logconfig_t *lcfg, const char *name,
 		break;

 	default:
+		INSIST(0);
 		ISC_UNREACHABLE();
 	}

@@ -695,7 +712,6 @@ isc_log_usechannel(isc_logconfig_t *lcfg, const char *name,
 		   const isc_logmodule_t *module) {
 	isc_log_t *lctx;
 	isc_logchannel_t *channel;
-	unsigned int i;

 	REQUIRE(VALID_CONFIG(lcfg));
 	REQUIRE(name != NULL);
@@ -724,7 +740,7 @@ isc_log_usechannel(isc_logconfig_t *lcfg, const char *name,
 		 * Assign to all categories.  Note that this includes
 		 * the default channel.
 		 */
-		for (i = 0; i < lctx->category_count; i++) {
+		for (size_t i = 0; i < lctx->category_count; i++) {
 			assignchannel(lcfg, i, module, channel);
 		}
 	}
@@ -787,32 +803,34 @@ isc_log_setcontext(isc_log_t *lctx) {

 void
 isc_log_setdebuglevel(isc_log_t *lctx, unsigned int level) {
-	isc_logchannel_t *channel;
-
 	REQUIRE(VALID_CONTEXT(lctx));

-	LOCK(&lctx->lock);
-
 	lctx->debug_level = level;
 	/*
 	 * Close ISC_LOG_DEBUGONLY channels if level is zero.
 	 */
-	if (lctx->debug_level == 0) {
-		for (channel = ISC_LIST_HEAD(lctx->logconfig->channels);
-		     channel != NULL; channel = ISC_LIST_NEXT(channel, link))
-		{
-			if (channel->type == ISC_LOG_TOFILE &&
-			    (channel->flags & ISC_LOG_DEBUGONLY) != 0 &&
-			    FILE_STREAM(channel) != NULL)
+	if (level == 0) {
+		RDLOCK(&lctx->lcfg_rwl);
+		isc_logconfig_t *lcfg = lctx->logconfig;
+		if (lcfg != NULL) {
+			LOCK(&lctx->lock);
+			for (isc_logchannel_t *channel =
+				     ISC_LIST_HEAD(lcfg->channels);
+			     channel != NULL;
+			     channel = ISC_LIST_NEXT(channel, link))
 			{
+				if (channel->type == ISC_LOG_TOFILE &&
+				    (channel->flags & ISC_LOG_DEBUGONLY) != 0 &&
+				    FILE_STREAM(channel) != NULL)
 				{
 					(void)fclose(FILE_STREAM(channel));
 					FILE_STREAM(channel) = NULL;
 				}
 			}
+			UNLOCK(&lctx->lock);
 		}
+		WRUNLOCK(&lctx->lcfg_rwl);
 	}
-	UNLOCK(&lctx->lock);
 }

 unsigned int
@@ -868,23 +886,24 @@ isc_log_opensyslog(const char *tag, int options, int facility) {

 void
 isc_log_closefilelogs(isc_log_t *lctx) {
-	isc_logchannel_t *channel;
-
 	REQUIRE(VALID_CONTEXT(lctx));

-	LOCK(&lctx->lock);
-	for (channel = ISC_LIST_HEAD(lctx->logconfig->channels);
-	     channel != NULL; channel = ISC_LIST_NEXT(channel, link))
-	{
-		if (channel->type == ISC_LOG_TOFILE &&
-		    FILE_STREAM(channel) != NULL) {
-			{
+	RDLOCK(&lctx->lcfg_rwl);
+	isc_logconfig_t *lcfg = lctx->logconfig;
+	if (lcfg != NULL) {
+		LOCK(&lctx->lock);
+		for (isc_logchannel_t *channel = ISC_LIST_HEAD(lcfg->channels);
+		     channel != NULL; channel = ISC_LIST_NEXT(channel, link))
+		{
+			if (channel->type == ISC_LOG_TOFILE &&
+			    FILE_STREAM(channel) != NULL) {
 				(void)fclose(FILE_STREAM(channel));
 				FILE_STREAM(channel) = NULL;
 			}
 		}
+		UNLOCK(&lctx->lock);
 	}
-	UNLOCK(&lctx->lock);
+	RDUNLOCK(&lctx->lcfg_rwl);
 }

 /****
@@ -1393,8 +1412,9 @@ isc_log_open(isc_logchannel_t *channel) {
 	return (result);
 }

-bool ISC_NO_SANITIZE
+bool
 isc_log_wouldlog(isc_log_t *lctx, int level) {
+	bool ret = false;
 	/*
 	 * Try to avoid locking the mutex for messages which can't
 	 * possibly be logged to any channels -- primarily debugging
@@ -1404,20 +1424,20 @@ isc_log_wouldlog(isc_log_t *lctx, int level) {
 	 * highest_level, or if there is a dynamic channel and the level is
 	 * less than or equal to the debug level, the main loop must be
 	 * entered to see if the message should really be output.
-	 *
-	 * NOTE: this is UNLOCKED access to the logconfig.  However,
-	 * the worst thing that can happen is that a bad decision is made
-	 * about returning without logging, and that's not a big concern,
-	 * because that's a risk anyway if the logconfig is being
-	 * dynamically changed.
 	 */
-
-	if (lctx == NULL || lctx->logconfig == NULL) {
+	if (lctx == NULL) {
 		return (false);
 	}

-	return (level <= lctx->logconfig->highest_level ||
-		(lctx->logconfig->dynamic && level <= lctx->debug_level));
+	RDLOCK(&lctx->lcfg_rwl);
+	isc_logconfig_t *lcfg = lctx->logconfig;
+	if (lcfg != NULL) {
+		ret = (level <= lcfg->highest_level ||
+		       (lcfg->dynamic && level <= lctx->debug_level));
+	}
+	RDUNLOCK(&lctx->lcfg_rwl);
+
+	return (ret);
 }

 static void
@@ -1434,7 +1454,6 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category,
 	bool matched = false;
 	bool printtime, iso8601, utc, printtag, printcolon;
 	bool printcategory, printmodule, printlevel, buffered;
-	isc_logconfig_t *lcfg;
 	isc_logchannel_t *channel;
 	isc_logchannellist_t *category_channels;
 	isc_result_t result;
@@ -1465,11 +1484,12 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category,
 	iso8601l_string[0] = '\0';
 	iso8601z_string[0] = '\0';

+	RDLOCK(&lctx->lcfg_rwl);
 	LOCK(&lctx->lock);

 	lctx->buffer[0] = '\0';

-	lcfg = lctx->logconfig;
+	isc_logconfig_t *lcfg = lctx->logconfig;

 	category_channels = ISC_LIST_HEAD(lcfg->channellists[category->id]);

@@ -1638,8 +1658,7 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category,
 						 * Unlock the mutex and
 						 * get the hell out of Dodge.
 						 */
-						UNLOCK(&lctx->lock);
-						return;
+						goto unlock;
 					}

 					message = ISC_LIST_NEXT(message, link);
@@ -1802,5 +1821,7 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category,
 		}
 	} while (1);

+unlock:
 	UNLOCK(&lctx->lock);
+	RDUNLOCK(&lctx->lcfg_rwl);
 }