From 4d58856ff76185d41405e28510343d88a633ec47 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Sur=C3=BD?= Date: Fri, 13 Mar 2020 15:16:14 +0100 Subject: [PATCH] Use isc_rwlock to lock .logconfig member of isc_log_t In isc_log_woudlog() the .logconfig member of isc_log_t structure was accessed unlocked on the merit that there could be just a race when .logconfig would be NULL, so the message would not be logged. This turned not to be true, as there's also data race deeper. The accessed isc_logconfig_t object could be in the middle of destruction, so the pointer would be still non-NULL, but the structure members could point to a chunk of memory no longer belonging to the object. Since we are only accessing integer types (the log level), this would never lead to a crash, it leads to memory access to memory area no longer belonging to the object and this a) wrong, b) raises a red flag in thread-safety tools. --- lib/isc/log.c | 104 ++++++++++++++++++++++++++++---------------------- 1 file changed, 58 insertions(+), 46 deletions(-) diff --git a/lib/isc/log.c b/lib/isc/log.c index 36ddb38e6b4..6689b2efa87 100644 --- a/lib/isc/log.c +++ b/lib/isc/log.c @@ -27,6 +27,7 @@ #include #include #include +#include #include #include #include @@ -39,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? */ @@ -137,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. */ - atomic_uintptr_t logconfig; char buffer[LOG_BUFFER_SIZE]; ISC_LIST(isc_logmessage_t) messages; }; @@ -253,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 @@ -269,7 +278,7 @@ isc_log_create(isc_mem_t *mctx, isc_log_t **lctxp, isc_logconfig_t **lcfgp) { sync_channellist(lcfg); - atomic_init(&lctx->logconfig, (uintptr_t)lcfg); + lctx->logconfig = lcfg; *lctxp = lctx; if (lcfgp != NULL) { @@ -350,8 +359,10 @@ isc_logconfig_use(isc_log_t *lctx, isc_logconfig_t *lcfg) { */ sync_channellist(lcfg); - old_cfg = (isc_logconfig_t *)atomic_exchange_acq_rel(&lctx->logconfig, - (uintptr_t)lcfg); + WRLOCK(&lctx->lcfg_rwl); + old_cfg = lctx->logconfig; + lctx->logconfig = lcfg; + WRUNLOCK(&lctx->lcfg_rwl); isc_logconfig_destroy(&old_cfg); } @@ -369,12 +380,16 @@ isc_log_destroy(isc_log_t **lctxp) { *lctxp = NULL; mctx = lctx->mctx; - lcfg = (isc_logconfig_t *)atomic_exchange_acq_rel(&lctx->logconfig, - (uintptr_t)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) { @@ -401,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; @@ -414,8 +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 && - atomic_load_acquire(&lcfg->lctx->logconfig) != (uintptr_t)lcfg); + REQUIRE(lcfg->lctx != NULL); + + RDLOCK(&lcfg->lctx->lcfg_rwl); + REQUIRE(lcfg->lctx->logconfig != lcfg); + RDUNLOCK(&lcfg->lctx->lcfg_rwl); mctx = lcfg->lctx->mctx; @@ -442,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)); @@ -673,6 +691,7 @@ isc_log_createchannel(isc_logconfig_t *lcfg, const char *name, break; default: + INSIST(0); ISC_UNREACHABLE(); } @@ -693,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); @@ -722,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); } } @@ -785,22 +803,19 @@ 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)); - REQUIRE(atomic_load_acquire(&lctx->logconfig) != (uintptr_t)NULL); - - LOCK(&lctx->lock); lctx->debug_level = level; /* * Close ISC_LOG_DEBUGONLY channels if level is zero. */ - if (lctx->debug_level == 0) { - isc_logconfig_t *lcfg = (isc_logconfig_t *)atomic_load_acquire( - &lctx->logconfig); + if (level == 0) { + RDLOCK(&lctx->lcfg_rwl); + isc_logconfig_t *lcfg = lctx->logconfig; if (lcfg != NULL) { - for (channel = ISC_LIST_HEAD(lcfg->channels); + LOCK(&lctx->lock); + for (isc_logchannel_t *channel = + ISC_LIST_HEAD(lcfg->channels); channel != NULL; channel = ISC_LIST_NEXT(channel, link)) { @@ -812,9 +827,10 @@ isc_log_setdebuglevel(isc_log_t *lctx, unsigned int level) { FILE_STREAM(channel) = NULL; } } + UNLOCK(&lctx->lock); } + WRUNLOCK(&lctx->lcfg_rwl); } - UNLOCK(&lctx->lock); } unsigned int @@ -870,16 +886,14 @@ 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); - isc_logconfig_t *lcfg = - (isc_logconfig_t *)atomic_load_acquire(&lctx->logconfig); + RDLOCK(&lctx->lcfg_rwl); + isc_logconfig_t *lcfg = lctx->logconfig; if (lcfg != NULL) { - for (channel = ISC_LIST_HEAD(lcfg->channels); channel != NULL; - channel = ISC_LIST_NEXT(channel, link)) + 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) { @@ -887,8 +901,9 @@ isc_log_closefilelogs(isc_log_t *lctx) { FILE_STREAM(channel) = NULL; } } + UNLOCK(&lctx->lock); } - UNLOCK(&lctx->lock); + RDUNLOCK(&lctx->lcfg_rwl); } /**** @@ -1397,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 @@ -1408,25 +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) { return (false); } - isc_logconfig_t *lcfg = - (isc_logconfig_t *)atomic_load_acquire(&lctx->logconfig); - if (lcfg == NULL) { - return (false); + 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 (level <= lcfg->highest_level || - (lcfg->dynamic && level <= lctx->debug_level)); + return (ret); } static void @@ -1443,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; @@ -1474,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 = (isc_logconfig_t *)atomic_load_acquire(&lctx->logconfig); + isc_logconfig_t *lcfg = lctx->logconfig; category_channels = ISC_LIST_HEAD(lcfg->channellists[category->id]); @@ -1647,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); @@ -1811,5 +1821,7 @@ isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category, } } while (1); +unlock: UNLOCK(&lctx->lock); + RDUNLOCK(&lctx->lcfg_rwl); } -- GitLab