[LOGCXX-231] Deadlock in AsyncAppender

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 0.10.0
• Fix Version/s: 0.10.0
• Component/s: Appender
• Environment: Windows with Visual Studio 8.0 SP1.
• Assignee: Curt Arnold
• Reporter: Jean-François Bastien
• Created: 05/Feb/08 13:56
• Updated: 03/Jun/08 13:48
• Resolved: 25/Mar/08 20:11

Description

I'm using an AsyncAppender that's initialized/accessed through/destroyed in a DLL through multiple other DLLs. My project is fairly complex, but I've succeeded in narrowing down the problem to a simple case. The following files reproduce the problem, although not 100% of the time:

---------------------------------------------------------------------------------------------------------------------
In an executable, the only file is:
#include "..\testlog4cxxdeadlockdll\dllmethods.h"

int main()
{
configure();

log();

shutdown();

return 0;
};
---------------------------------------------------------------------------------------------------------------------

---------------------------------------------------------------------------------------------------------------------
In a DLL, the following header file:
#define DLL_EXPORT __declspec(dllexport)
#define DLL_IMPORT __declspec(dllimport)
#if defined(DLLTEST)

1. define DLLTEST_DLL DLL_EXPORT
   #else
2. define DLLTEST_DLL DLL_IMPORT
   #endif

DLLTEST_DLL void configure();

DLLTEST_DLL void log();

DLLTEST_DLL void shutdown();
---------------------------------------------------------------------------------------------------------------------

---------------------------------------------------------------------------------------------------------------------
In the same DLL, the following CPP file:
#define DLLTEST

#include "dllmethods.h"

#ifdef _MSC_VER

1. pragma warning(push)
2. pragma warning(disable : 4250) // Inherits via dominance.
3. pragma warning(disable : 4251) // Class needs to have dll-interface to be used by clients.
   #endif
   #include <log4cxx/logger.h>
   #include <log4cxx/logmanager.h>
   #include <log4cxx/patternlayout.h>
   #include <log4cxx/xml/xmllayout.h>
   #include <log4cxx/asyncappender.h>
   #include <log4cxx/fileappender.h>
   #include <log4cxx/spi/loggerrepository.h>
   #include <log4cxx/defaultloggerfactory.h>
   #ifdef _MSC_VER
4. pragma warning(pop)
   #endif

#include <exception>
#include <iostream>

void configure()
{
::log4cxx::LogManager::getLoggerRepository()->setConfigured(true);

// Create an asynchronous appender which will append to other appenders.
::log4cxx::AsyncAppenderPtr wAsynchronousAppender(new ::log4cxx::AsyncAppender);

{ const int wBufferSize(1 << 8); const bool wBlocking (false); wAsynchronousAppender->setName(LOG4CXX_STR("AsynchronousAppender")); wAsynchronousAppender->setBufferSize(wBufferSize); wAsynchronousAppender->setBlocking(wBlocking); ::log4cxx::LoggerPtr wRoot(::log4cxx::Logger::getRootLogger()); wRoot->addAppender(wAsynchronousAppender); }

const ::log4cxx::LogString wFileName(LOG4CXX_STR("logtest.log"));

{ const ::log4cxx::LogString sPattern (LOG4CXX_STR("%d, %c, %t, %p, %m%n")); ::log4cxx::LayoutPtr wLayout (new ::log4cxx::PatternLayout(sPattern)); const bool wAppendToFile(false); ::log4cxx::AppenderPtr wAppender (new ::log4cxx::FileAppender(wLayout, wFileName, wAppendToFile)); wAppender->setName(LOG4CXX_STR("PatternFileAppender")); wAsynchronousAppender->addAppender(wAppender); }

// Unbuffered file appender with an XML pattern layout compatible with the log4j format (thus with Chainsaw).
{
::log4cxx::xml::XMLLayoutPtr wLayout (new ::log4cxx::xml::XMLLayout);
const bool wAppendToFile (false);
const ::log4cxx::LogString wFileNamePostfix(LOG4CXX_STR(".xml"));
::log4cxx::AppenderPtr wAppender (new ::log4cxx::FileAppender(wLayout,
wFileName + wFileNamePostfix,
wAppendToFile));
wAppender->setName(LOG4CXX_STR("XmlFileAppender"));
wAsynchronousAppender->addAppender(wAppender);
}

const ::log4cxx::LogString wLoggerName(LOG4CXX_STR("Unknown"));
::log4cxx::spi::LoggerFactoryPtr wLoggerFactory(new ::log4cxx::DefaultLoggerFactory());
::log4cxx::LoggerPtr wLogger(::log4cxx::LogManager::getLoggerRepository()->getLogger(wLoggerName, wLoggerFactory));
wLogger->setAdditivity(true);
}

void shutdown()
{
try
{
::log4cxx::LogManager::shutdown();
}
catch(const std::exception & e)

{ std::cerr << "Standard exception while trying to shutdown log4cxx: " << e.what() << std::endl; }

catch(...)

{ std::cerr << "Unknown exception while trying to shutdown log4cxx." << std::endl; }

}

void log()
{
::log4cxx::LoggerPtr logger(::log4cxx::Logger::getLogger(LOG4CXX_STR("Unknown")));

for(int i(0); i < 10000; ++i)
{
::log4cxx::helpers::MessageBuffer oss_;
logger->forcedLog(::log4cxx::Level::getWarn(), oss_.str(oss_ << "TEST " << i), LOG4CXX_LOCATION);
}
}
---------------------------------------------------------------------------------------------------------------------

The problem happens when shutdown is invoked.
AsyncAppender::close() is called, which does dispatcher.join();
This calls Thread::join(), which does apr_status_t stat = apr_thread_join(&startStat, (apr_thread_t*) thread);
Then in APR_DECLARE(apr_status_t) apr_thread_join(apr_status_t *retval, apr_thread_t *thd), there is rv = WaitForSingleObject(thd->td, INFINITE);

And that's where the deadlock happens. It seems that the wait on the thread never finishes, and the process hangs.

Please tell me if it's my usage of log4cxx that's wrong, or if there indeed is a problem with the AsyncAppender.