Improve AsyncAppender unit test reliability (#544)
* Use a separate test for logging from an appender
* Check the discard logic corresponds to the documented behaviour
* Add debug to show which messages were discarded
* Ensure appender logged events are discarded when the buffer is full
* Ensure only appender logged events are discarded when Blocking mode is on
* Do not wait on the dispatch thread when an attached appender logged the event
diff --git a/src/main/cpp/asyncappender.cpp b/src/main/cpp/asyncappender.cpp
index cec9f35..2427cb6 100644
--- a/src/main/cpp/asyncappender.cpp
+++ b/src/main/cpp/asyncappender.cpp
@@ -227,7 +227,7 @@
/**
* Used to ensure the dispatch thread does not wait when a logging thread is waiting.
*/
- int blockedCount{0};
+ alignas(hardware_constructive_interference_size) int blockedCount{0};
};
@@ -285,6 +285,7 @@
if (priv->bufferSize <= 0)
{
priv->appenders.appendLoopOnAppenders(event, p);
+ return;
}
// Get a copy of this thread's diagnostic context
@@ -296,6 +297,7 @@
if (!priv->dispatcher.joinable())
priv->dispatcher = ThreadUtility::instance()->createThread( LOG4CXX_STR("AsyncAppender"), &AsyncAppender::dispatch, this );
}
+ bool isDispatchThread = (priv->dispatcher.get_id() == std::this_thread::get_id());
while (true)
{
auto pendingCount = priv->eventCount - priv->dispatchedCount;
@@ -305,7 +307,7 @@
auto oldEventCount = priv->eventCount++;
auto index = oldEventCount % priv->buffer.size();
// Wait for a free slot
- while (priv->bufferSize <= oldEventCount - priv->dispatchedCount)
+ while (priv->bufferSize <= oldEventCount - priv->dispatchedCount && !isDispatchThread)
std::this_thread::yield(); // Allow the dispatch thread to free a slot
// Write to the ring buffer
priv->buffer[index] = AsyncAppenderPriv::EventData{event, pendingCount};
@@ -334,7 +336,7 @@
if (priv->blocking
&& !priv->closed
- && (priv->dispatcher.get_id() != std::this_thread::get_id()) )
+ && !isDispatchThread)
{
++priv->blockedCount;
priv->bufferNotFull.wait(lock, [this]()
@@ -525,6 +527,9 @@
void AsyncAppender::dispatch()
{
size_t discardCount = 0;
+ size_t iterationCount = 0;
+ size_t waitCount = 0;
+ size_t blockedCount = 0;
std::vector<size_t> pendingCountHistogram(priv->bufferSize, 0);
bool isActive = true;
@@ -537,6 +542,7 @@
std::this_thread::yield(); // Wait a bit
if (priv->dispatchedCount == priv->commitCount)
{
+ ++waitCount;
std::unique_lock<std::mutex> lock(priv->bufferMutex);
priv->bufferNotEmpty.wait(lock, [this]() -> bool
{ return 0 < priv->blockedCount || priv->dispatchedCount != priv->commitCount || priv->closed; }
@@ -556,6 +562,7 @@
priv->bufferNotFull.notify_all();
{
std::lock_guard<std::mutex> lock(priv->bufferMutex);
+ blockedCount += priv->blockedCount;
for (auto discardItem : priv->discardMap)
{
events.push_back(discardItem.second.createEvent(p));
@@ -587,11 +594,24 @@
}
}
}
+ ++iterationCount;
}
if (LogLog::isDebugEnabled())
{
Pool p;
LogString msg(LOG4CXX_STR("AsyncAppender"));
+#ifdef _DEBUG
+ msg += LOG4CXX_STR(" iterationCount ");
+ StringHelper::toString(iterationCount, p, msg);
+ msg += LOG4CXX_STR(" waitCount ");
+ StringHelper::toString(waitCount, p, msg);
+ msg += LOG4CXX_STR(" blockedCount ");
+ StringHelper::toString(blockedCount, p, msg);
+ msg += LOG4CXX_STR(" commitCount ");
+ StringHelper::toString(priv->commitCount, p, msg);
+#endif
+ msg += LOG4CXX_STR(" dispatchedCount ");
+ StringHelper::toString(priv->dispatchedCount, p, msg);
msg += LOG4CXX_STR(" discardCount ");
StringHelper::toString(discardCount, p, msg);
msg += LOG4CXX_STR(" pendingCountHistogram");
diff --git a/src/test/cpp/asyncappendertestcase.cpp b/src/test/cpp/asyncappendertestcase.cpp
index 206efc1..28b2c9e 100644
--- a/src/test/cpp/asyncappendertestcase.cpp
+++ b/src/test/cpp/asyncappendertestcase.cpp
@@ -18,7 +18,7 @@
#define NOMINMAX
#include "logunit.h"
-#include <log4cxx/logger.h>
+#include <log4cxx/loggerinstance.h>
#include <log4cxx/logmanager.h>
#include <log4cxx/simplelayout.h>
#include "vectorappender.h"
@@ -87,18 +87,6 @@
{
std::lock_guard<std::mutex> lock( blocker );
VectorAppender::append(event, p);
-
- //
- // if fatal, echo messages for testLoggingInDispatcher
- //
- if (event->getLevel() == Level::getInfo())
- {
- LoggerPtr logger = Logger::getLoggerLS(event->getLoggerName());
- LOG4CXX_LOGLS(logger, Level::getError(), event->getMessage());
- LOG4CXX_LOGLS(logger, Level::getWarn(), event->getMessage());
- LOG4CXX_LOGLS(logger, Level::getInfo(), event->getMessage());
- LOG4CXX_LOGLS(logger, Level::getDebug(), event->getMessage());
- }
}
std::mutex& getBlocker()
@@ -108,7 +96,24 @@
};
-LOG4CXX_PTR_DEF(BlockableVectorAppender);
+/**
+ * An appender that adds logging events
+ */
+class LoggingVectorAppender : public VectorAppender
+{
+ LoggerInstancePtr logger{ "LoggingVectorAppender" };
+ void append(const spi::LoggingEventPtr& event, log4cxx::helpers::Pool& p) override
+ {
+ VectorAppender::append(event, p);
+ if (event->getMessage() == LOG4CXX_STR("Hello, World"))
+ {
+ LOG4CXX_LOGLS(logger, Level::getError(), LOG4CXX_STR("Some example error"));
+ LOG4CXX_LOGLS(logger, Level::getWarn(), LOG4CXX_STR("Some example warning"));
+ LOG4CXX_LOGLS(logger, Level::getInfo(), LOG4CXX_STR("Some information"));
+ LOG4CXX_LOGLS(logger, Level::getDebug(), LOG4CXX_STR("Some detailed data"));
+ }
+ }
+};
/**
* Tests of AsyncAppender.
@@ -128,6 +133,7 @@
LOGUNIT_TEST(testMultiThread);
LOGUNIT_TEST(testBadAppender);
LOGUNIT_TEST(testBufferOverflowBehavior);
+ LOGUNIT_TEST(testLoggingAppender);
#if LOG4CXX_HAS_DOMCONFIGURATOR
LOGUNIT_TEST(testConfiguration);
#endif
@@ -322,9 +328,9 @@
*/
void testBufferOverflowBehavior()
{
- BlockableVectorAppenderPtr blockableAppender = BlockableVectorAppenderPtr(new BlockableVectorAppender());
+ auto blockableAppender = std::make_shared<BlockableVectorAppender>();
blockableAppender->setName(LOG4CXX_STR("async-blockableVector"));
- AsyncAppenderPtr async = AsyncAppenderPtr(new AsyncAppender());
+ auto async = std::make_shared<AsyncAppender>();
async->setName(LOG4CXX_STR("async-testBufferOverflowBehavior"));
async->addAppender(blockableAppender);
async->setBufferSize(5);
@@ -332,7 +338,7 @@
async->setBlocking(false);
Pool p;
async->activateOptions(p);
- LoggerPtr rootLogger = Logger::getRootLogger();
+ auto rootLogger = Logger::getRootLogger();
rootLogger->addAppender(async);
LOG4CXX_INFO(rootLogger, "Hello, World"); // This causes the dispatch thread creation
std::this_thread::sleep_for( std::chrono::milliseconds( 10 ) ); // Wait for the dispatch thread to be ready
@@ -347,16 +353,108 @@
LOG4CXX_ERROR(rootLogger, "That's all folks.");
}
async->close();
- const std::vector<spi::LoggingEventPtr>& events = blockableAppender->getVector();
+
+ // Check which messages were output
+ auto& events = blockableAppender->getVector();
LOGUNIT_ASSERT(!events.empty());
+ LOGUNIT_ASSERT(events.size() <= 142);
LoggingEventPtr initialEvent = events.front();
- LoggingEventPtr discardEvent = events.back();
LOGUNIT_ASSERT(initialEvent->getMessage() == LOG4CXX_STR("Hello, World"));
- LOGUNIT_ASSERT(discardEvent->getMessage().substr(0, 10) == LOG4CXX_STR("Discarded "));
+ std::map<LevelPtr, int> levelCount;
+ int discardMessageCount{ 0 };
+ LoggingEventPtr discardEvent;
+ for (auto& e : events)
+ {
+ ++levelCount[e->getLevel()];
+ if (e->getMessage().substr(0, 10) == LOG4CXX_STR("Discarded "))
+ {
+ ++discardMessageCount;
+ discardEvent = e;
+ }
+ }
+ if (helpers::LogLog::isDebugEnabled())
+ {
+ LogString msg{ LOG4CXX_STR("messageCounts:") };
+ for (auto& item : levelCount)
+ {
+ msg += LOG4CXX_STR(" ");
+ msg += item.first->toString();
+ msg += LOG4CXX_STR(" ");
+ StringHelper::toString(item.second, p, msg);
+ }
+ msg += LOG4CXX_STR(" ");
+ msg += LOG4CXX_STR("Discarded ");
+ StringHelper::toString(discardMessageCount, p, msg);
+ helpers::LogLog::debug(msg);
+ }
+ // Check this test has activated the discard logic
+ LOGUNIT_ASSERT(1 <= discardMessageCount);
+ LOGUNIT_ASSERT(5 < levelCount[Level::getInfo()]);
+ // Check the discard message is the logging event of the highest level
+ LOGUNIT_ASSERT_EQUAL(levelCount[Level::getError()], 1);
+ LOGUNIT_ASSERT_EQUAL(discardEvent->getLevel(), Level::getError());
+ // Check the discard message does not have location info
LOGUNIT_ASSERT_EQUAL(log4cxx::spi::LocationInfo::getLocationUnavailable().getClassName(),
discardEvent->getLocationInformation().getClassName());
}
+ /**
+ * Tests behavior when the appender attached to a AsyncAppender adds logging events
+ */
+ void testLoggingAppender()
+ {
+ auto loggingAppender = std::make_shared<LoggingVectorAppender>();
+ loggingAppender->setName(LOG4CXX_STR("loggingAppender"));
+ auto async = std::make_shared<AsyncAppender>();
+ async->setName(LOG4CXX_STR("withLoggingAppender"));
+ async->addAppender(loggingAppender);
+ async->setBufferSize(5);
+ async->setLocationInfo(true);
+ Pool p;
+ async->activateOptions(p);
+ auto rootLogger = Logger::getRootLogger();
+ rootLogger->addAppender(async);
+ LOG4CXX_INFO(rootLogger, "Hello, World"); // This causes the dispatch thread creation
+ std::this_thread::sleep_for( std::chrono::milliseconds( 10 ) ); // Wait for the dispatch thread to be ready
+ for (int i = 0; i < 10; i++)
+ {
+ LOG4CXX_INFO(rootLogger, "Hello, World");
+ }
+ LOG4CXX_INFO(rootLogger, "Bye bye World");
+ std::this_thread::sleep_for( std::chrono::milliseconds( 10 ) ); // Wait for the dispatch thread take the above events
+ async->close();
+ auto& events = loggingAppender->getVector();
+ std::map<LevelPtr, int> levelCount;
+ int discardMessageCount{ 0 };
+ for (auto& e : events)
+ {
+ ++levelCount[e->getLevel()];
+ auto message = e->getMessage();
+ if (message.substr(0, 10) == LOG4CXX_STR("Discarded "))
+ {
+ ++discardMessageCount;
+ auto isAppenderMessage = (message.npos == message.find(LOG4CXX_STR("World")));
+ LOGUNIT_ASSERT(isAppenderMessage);
+ }
+ }
+ if (helpers::LogLog::isDebugEnabled())
+ {
+ LogString msg{ LOG4CXX_STR("messageCounts:") };
+ for (auto& item : levelCount)
+ {
+ msg += LOG4CXX_STR(" ");
+ msg += item.first->toString();
+ msg += LOG4CXX_STR(" ");
+ StringHelper::toString(item.second, p, msg);
+ }
+ msg += LOG4CXX_STR(" ");
+ msg += LOG4CXX_STR("Discarded ");
+ StringHelper::toString(discardMessageCount, p, msg);
+ helpers::LogLog::debug(msg);
+ }
+ LOGUNIT_ASSERT(12 < events.size());
+ }
+
#if LOG4CXX_HAS_DOMCONFIGURATOR
void testConfiguration()
{
