From f8dee56243d7378864fdcdcc21262fc563639827 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 23 Mar 2010 14:11:50 +0100 Subject: bugfix: potential re-use of free()ed file stream object in omfile when dynaCache is enabled, the cache is full, a new entry needs to be allocated, thus the LRU discarded, then a new entry is opend and that fails. In that case, it looks like the discarded stream may be reused improperly (based on code analysis, test case and confirmation pending) --- tools/omfile.c | 28 +++++++++++++++++++++------- 1 file changed, 21 insertions(+), 7 deletions(-) (limited to 'tools/omfile.c') diff --git a/tools/omfile.c b/tools/omfile.c index 0f27f1e9..ae5f350d 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -286,13 +286,15 @@ dynaFileDelCacheEntry(dynaFileCacheEntry **pCache, int iEntry, int bFreeEntry) DBGPRINTF("Removed entry %d for file '%s' from dynaCache.\n", iEntry, pCache[iEntry]->pName == NULL ? UCHAR_CONSTANT("[OPEN FAILED]") : pCache[iEntry]->pName); - /* if the name is NULL, this is an improperly initilized entry which +// RG: check the "open failed" case -- can this cause trouble (but do we have that situation?) + /* if the name is NULL, this is an improperly initialized entry which * needs to be discarded. In this case, neither the file is to be closed - * not the name to be freed. + * nor the name to be freed. */ if(pCache[iEntry]->pName != NULL) { if(pCache[iEntry]->pStrm != NULL) strm.Destruct(&pCache[iEntry]->pStrm); +// RG: pStrm should now be NULL... d_free(pCache[iEntry]->pName); pCache[iEntry]->pName = NULL; } @@ -474,7 +476,7 @@ prepareDynFile(instanceData *pData, uchar *newFileName, unsigned iMsgOpts) if(iFirstFree == -1) iFirstFree = i; } else { /* got an element, let's see if it matches */ - if(!ustrcmp(newFileName, pCache[i]->pName)) { + if(!ustrcmp(newFileName, pCache[i]->pName)) { // RG: name == NULL? /* we found our element! */ pData->pStrm = pCache[i]->pStrm; pData->iCurrElt = i; @@ -497,24 +499,38 @@ prepareDynFile(instanceData *pData, uchar *newFileName, unsigned iMsgOpts) * is error-prone, so I prefer to do it here. -- rgerhards, 2010-03-02 */ pData->iCurrElt = -1; + /* similarly, we need to set the current pStrm to NULL, because otherwise, if prepareFile() fails, + * we may end up using an old stream. This bug depends on how exactly prepareFile fails, + * but it* could be triggered in the common case of a failed open() system call. + * rgerhards, 2010-03-22 + */ + pData->pStrm = NULL; if(iFirstFree == -1 && (pData->iCurrCacheSize < pData->iDynaFileCacheSize)) { /* there is space left, so set it to that index */ iFirstFree = pData->iCurrCacheSize++; } +// RG: this is the begin of a potential problem area + /* Note that the following code sequence does not work with the cache entry itself, + * but rather with pData->pStrm, the (sole) stream pointer in the non-dynafile case. + * The cache array is only updated after the open was successful. -- rgerhards, 2010-03-21 + */ if(iFirstFree == -1) { dynaFileDelCacheEntry(pCache, iOldest, 0); iFirstFree = iOldest; /* this one *is* now free ;) */ } else { /* we need to allocate memory for the cache structure */ + /* TODO: performance note: we could alloc all entries on startup, thus saving malloc + * overhead -- this may be something to consider in v5... + */ CHKmalloc(pCache[iFirstFree] = (dynaFileCacheEntry*) calloc(1, sizeof(dynaFileCacheEntry))); } /* Ok, we finally can open the file */ localRet = prepareFile(pData, newFileName); /* ignore exact error, we check fd below */ - /* file is either open now or an error state set */ + /* file is either open now or an error state set */ // RG: better check localRet? if(pData->pStrm == NULL) { /* do not report anything if the message is an internally-generated * message. Otherwise, we could run into a never-ending loop. The bad @@ -525,13 +541,11 @@ prepareDynFile(instanceData *pData, uchar *newFileName, unsigned iMsgOpts) } else { errmsg.LogError(0, NO_ERRCODE, "Could not open dynamic file '%s' - discarding message", newFileName); } - dynaFileDelCacheEntry(pCache, iFirstFree, 1); ABORT_FINALIZE(localRet); } if((pCache[iFirstFree]->pName = ustrdup(newFileName)) == NULL) { - /* we need to discard the entry, otherwise things could lead to a segfault! */ - dynaFileDelCacheEntry(pCache, iFirstFree, 1); + strm.Destruct(&pData->pStrm); /* need to free failed entry! */ ABORT_FINALIZE(RS_RET_OUT_OF_MEMORY); } pCache[iFirstFree]->pStrm = pData->pStrm; -- cgit v1.2.3 From 5d58774813d4ecd4fc9f8230f8d5446457eb2ed5 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 23 Mar 2010 14:21:33 +0100 Subject: streamline dynafile cache entry deletion a bit The old code looks a bit "strange", though not necessarily incorrect. The new code looks correct and is probably less irritating during bug hunting. --- tools/omfile.c | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) (limited to 'tools/omfile.c') diff --git a/tools/omfile.c b/tools/omfile.c index ae5f350d..91bcf0c2 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -286,19 +286,18 @@ dynaFileDelCacheEntry(dynaFileCacheEntry **pCache, int iEntry, int bFreeEntry) DBGPRINTF("Removed entry %d for file '%s' from dynaCache.\n", iEntry, pCache[iEntry]->pName == NULL ? UCHAR_CONSTANT("[OPEN FAILED]") : pCache[iEntry]->pName); -// RG: check the "open failed" case -- can this cause trouble (but do we have that situation?) - /* if the name is NULL, this is an improperly initialized entry which - * needs to be discarded. In this case, neither the file is to be closed - * nor the name to be freed. - */ + if(pCache[iEntry]->pName != NULL) { - if(pCache[iEntry]->pStrm != NULL) - strm.Destruct(&pCache[iEntry]->pStrm); -// RG: pStrm should now be NULL... d_free(pCache[iEntry]->pName); pCache[iEntry]->pName = NULL; } + if(pCache[iEntry]->pStrm != NULL) { + strm.Destruct(&pCache[iEntry]->pStrm); + if(pCache[iEntry]->pStrm != NULL) /* safety check -- TODO: remove if no longer necessary */ + abort(); + } + if(bFreeEntry) { d_free(pCache[iEntry]); pCache[iEntry] = NULL; -- cgit v1.2.3 From 28b3703c95cb06642ff245f4d7e265c4591c128f Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 25 Mar 2010 07:56:03 +0100 Subject: bugfix: potential segfault in dynafile cache This bug was triggered by an open failure. The the cache was full and a new entry needed to be placed inside it, a victim for eviction was selected. That victim was freed, then the open of the new file tried. If the open failed, the victim entry was still freed, and the function exited. However, on next invocation and cache search, the victim entry was used as if it were populated, most probably resulting in a segfault. --- tools/omfile.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'tools/omfile.c') diff --git a/tools/omfile.c b/tools/omfile.c index 91bcf0c2..2a14f45b 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -471,7 +471,7 @@ prepareDynFile(instanceData *pData, uchar *newFileName, unsigned iMsgOpts) iOldest = 0; /* we assume the first element to be the oldest - that will change as we loop */ ttOldest = time(NULL) + 1; /* there must always be an older one */ for(i = 0 ; i < pData->iCurrCacheSize ; ++i) { - if(pCache[i] == NULL) { + if(pCache[i] == NULL || pCache[i]->pName == NULL) { if(iFirstFree == -1) iFirstFree = i; } else { /* got an element, let's see if it matches */ -- cgit v1.2.3 From bcddd30c2e9d8594a67a853c389c4424aa0c6524 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 25 Mar 2010 08:13:58 +0100 Subject: undo experimental commit dccadb677c5a6b8379f631e4c1f14c8c4089d4a6 Further testing turned out that the rsyslog core works correctly and this fix is not needed. The concurrency we saw was actually caused by other actions (even processes) during directory creation. See commit 9e5b31fc44136dbcc1e443cfe7714e9daf97d844 for further details. --- tools/omfile.c | 9 --------- 1 file changed, 9 deletions(-) (limited to 'tools/omfile.c') diff --git a/tools/omfile.c b/tools/omfile.c index 2a14f45b..774f0b96 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -48,7 +48,6 @@ #include #include #include -#include #ifdef OS_SOLARIS # include @@ -66,7 +65,6 @@ #include "stream.h" #include "unicode-helper.h" #include "atomic.h" -#include "debug.h" MODULE_TYPE_OUTPUT @@ -136,7 +134,6 @@ typedef struct _instanceData { int iIOBufSize; /* size of associated io buffer */ int iFlushInterval; /* how fast flush buffer on inactivity? */ bool bFlushOnTXEnd; /* flush write buffers when transaction has ended? */ - pthread_mutex_t mutEx; /* guard ourselves against being called multiple times with the same instance */ } instanceData; @@ -619,7 +616,6 @@ finalize_it: BEGINcreateInstance CODESTARTcreateInstance pData->pStrm = NULL; - pthread_mutex_init(&pData->mutEx, NULL); ENDcreateInstance @@ -629,7 +625,6 @@ CODESTARTfreeInstance dynaFileFreeCache(pData); } else if(pData->pStrm != NULL) strm.Destruct(&pData->pStrm); - pthread_mutex_destroy(&pData->mutEx); ENDfreeInstance @@ -639,7 +634,6 @@ ENDtryResume BEGINdoAction CODESTARTdoAction - d_pthread_mutex_lock(&pData->mutEx); DBGPRINTF("file to log to: %s\n", pData->f_fname); CHKiRet(writeFile(ppString, iMsgOpts, pData)); if(pData->bFlushOnTXEnd) { @@ -647,7 +641,6 @@ CODESTARTdoAction CHKiRet(strm.Flush(pData->pStrm)); } finalize_it: - d_pthread_mutex_unlock(&pData->mutEx); ENDdoAction @@ -784,7 +777,6 @@ static rsRetVal resetConfigVariables(uchar __attribute__((unused)) *pp, void __a BEGINdoHUP CODESTARTdoHUP - d_pthread_mutex_lock(&pData->mutEx); if(pData->bDynamicName) { dynaFileFreeCacheEntries(pData); } else { @@ -793,7 +785,6 @@ CODESTARTdoHUP pData->pStrm = NULL; } } - d_pthread_mutex_unlock(&pData->mutEx); ENDdoHUP -- cgit v1.2.3