search

apache / logging-log4cxx

Apache Log4cxx is a C++ port of Apache Log4j
http://logging.apache.org/log4cxx
Apache License 2.0
278 stars 122 forks source link

Prevent potential deadlock on shutdown when using AsyncAppender #396

Closed swebb2066 closed 4 months ago

swebb2066 commented 4 months ago

Occasionally (50 -400 invocations) asyncappendertestcase does not terminate. The process state on one such instance is as follows:

Attaching to program: C:\msys64\home\steph\logging-log4cxx\build\src\test\cpp\asyncappendertestcase.exe, process 20424
[New Thread 20424.0x7f14]
[New Thread 20424.0x4210]
(gdb) thread bt
Invalid thread ID: bt
(gdb) thread apply all bt

Thread 3 (Thread 20424.0x4210):
#0  0x00007ff8b24d3c91 in ntdll!DbgBreakPoint () from C:\WINDOWS\SYSTEM32\ntdll.dll
#1  0x00007ff8b25070fe in ntdll!DbgUiRemoteBreakin () from C:\WINDOWS\SYSTEM32\ntdll.dll
#2  0x00007ff8b114257d in KERNEL32!BaseThreadInitThunk () from C:\WINDOWS\System32\kernel32.dll
#3  0x00007ff8b248af28 in ntdll!RtlUserThreadStart () from C:\WINDOWS\SYSTEM32\ntdll.dll
#4  0x0000000000000000 in ?? ()

Thread 2 (Thread 20424.0x7f14):
#0  0x00007ff8b24d0024 in ntdll!ZwWaitForSingleObject () from C:\WINDOWS\SYSTEM32\ntdll.dll
#1  0x00007ff8af889a9e in WaitForSingleObjectEx () from C:\WINDOWS\System32\KernelBase.dll
#2  0x00007ff89a132fe9 in ?? () from C:\msys64\ucrt64\bin\libwinpthread-1.dll
#3  0x00007fff92ee3421 in __gthread_mutex_lock(long long*) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#4  0x00007fff92ee3479 in __gthread_recursive_mutex_lock(long long*) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#5  0x00007fff92fc92f8 in std::recursive_mutex::lock() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#6  0x00007fff92f8c28a in std::lock_guard<std::recursive_mutex>::lock_guard(std::recursive_mutex&) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#7  0x00007fff92f01956 in log4cxx::Hierarchy::fireRemoveAppenderEvent(log4cxx::Logger const*, log4cxx::Appender const*) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#8  0x00007fff92f11498 in log4cxx::Logger::removeAppender(std::shared_ptr<log4cxx::Appender>) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#9  0x00007fff92ef628e in log4cxx::varia::FallbackErrorHandler::error(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::exception const&, int, std::shared_ptr<log4cxx::spi::LoggingEvent> const&) const () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#10 0x00007fff92ee7acb in log4cxx::AsyncAppender::dispatch() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#11 0x00007fff9300bd96 in void std::__invoke_impl<void, void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*>(std::__invoke_memfun_deref, void (log4cxx::AsyncAppender::*&&)(), log4cxx::AsyncAppender*&&) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#12 0x00007fff9301b8ac in std::__invoke_result<void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*>::type std::__invoke<void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*>(void (log4cxx::AsyncAppender::*&&)(), log4cxx::AsyncAppender*&&) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#13 0x00007fff92fe1365 in void std::thread::_Invoker<std::tuple<void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*> >::_M_invoke<0ull, 1ull>(std::_Index_tuple<0ull, 1ull>) () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#14 0x00007fff92fe13d8 in std::thread::_Invoker<std::tuple<void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*> >::operator()() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#15 0x00007fff92fe0e7c in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*> > >::_M_run() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#16 0x00007fff933e53ff in ?? () from C:\msys64\ucrt64\bin\libstdc++-6.dll
#17 0x00007ff89a134dbb in ?? () from C:\msys64\ucrt64\bin\libwinpthread-1.dll
#18 0x00007ff8aff09333 in ucrtbase!_recalloc () from C:\WINDOWS\System32\ucrtbase.dll
#19 0x00007ff8b114257d in KERNEL32!BaseThreadInitThunk () from C:\WINDOWS\System32\kernel32.dll
#20 0x00007ff8b248af28 in ntdll!RtlUserThreadStart () from C:\WINDOWS\SYSTEM32\ntdll.dll
#21 0x0000000000000000 in ?? ()

Thread 1 (Thread 20424.0x596c):
#0  0x00007ff8b24d0024 in ntdll!ZwWaitForSingleObject () from C:\WINDOWS\SYSTEM32\ntdll.dll
#1  0x00007ff8af889a9e in WaitForSingleObjectEx () from C:\WINDOWS\System32\KernelBase.dll
#2  0x00007ff89a13689a in ?? () from C:\msys64\ucrt64\bin\libwinpthread-1.dll
#3  0x00007fff9339e4f7 in ?? () from C:\msys64\ucrt64\bin\libstdc++-6.dll
#4  0x00007fff92f57703 in log4cxx::AsyncAppender::AsyncAppenderPriv::stopDispatcher() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#5  0x00007fff92ee6515 in log4cxx::AsyncAppender::close() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#6  0x00007fff92f0fcc4 in log4cxx::Logger::closeNestedAppenders() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#7  0x00007fff92f02627 in log4cxx::Hierarchy::shutdownInternal() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#8  0x00007fff92f02589 in log4cxx::Hierarchy::shutdown() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#9  0x00007fff92f15ea7 in log4cxx::LogManager::shutdown() () from C:\msys64\home\steph\logging-log4cxx\build\src\main\cpp\liblog4cxx.dll
#10 0x00007ff71b6b8681 in AsyncAppenderTestCase::tearDown() ()
#11 0x00007ff71b6b9927 in void LogUnit::runTest<AsyncAppenderTestCase>(abts_case*, void (AsyncAppenderTestCase::*)()) ()
#12 0x00007ff71b6b5838 in AsyncAppenderTestCase::RegisterSuite::testBadAppenderRegistration::run(abts_case*, void*) ()
#13 0x00007ff71b6b1b92 in abts_run_test(abts_suite*, char const*, void (*)(abts_case*, void*), void*) ()
#14 0x00007ff71b6b367e in LogUnit::TestSuite::run(abts_suite*) const ()
#15 0x00007ff71b6b2d1c in abts_run_suites(abts_suite*) ()
#16 0x00007ff71b6b27ac in main ()

The Log4cxx debug output in this instance was:

asyncappendertestcase.: -log4cxx: Started
\log4cxx: Checking file log4cxx.xml
log4cxx: Checking file log4cxx.properties
log4cxx: Checking file log4j.xml
log4cxx: Checking file log4j.properties
log4cxx: Could not find default configuration file.
log4cxx: AsyncAppender discardCount 0 pendingCountHistogram 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
log4cxx: Attempted to append to closed appender named [async-CloseTest].
-log4cxx: Checking file log4cxx.xml
log4cxx: Checking file log4cxx.properties
log4cxx: Checking file log4j.xml
log4cxx: Checking file log4j.properties
log4cxx: Could not find default configuration file.
log4cxx: AsyncAppender discardCount 0 pendingCountHistogram 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
log4cxx: Attempted to append to closed appender named [async-test2].
|log4cxx: Checking file log4cxx.xml
log4cxx: Checking file log4cxx.properties
log4cxx: Checking file log4j.xml
log4cxx: Checking file log4j.properties
log4cxx: Could not find default configuration file.
log4cxx: AsyncAppender discardCount 0 pendingCountHistogram 3 3 3 3 3 3 3 3 3 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 2 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
log4cxx: Attempted to append to closed appender named [async-testEventFlush].
/log4cxx: Checking file log4cxx.xml
log4cxx: Checking file log4cxx.properties
log4cxx: Checking file log4j.xml
log4cxx: Checking file log4j.properties
log4cxx: Could not find default configuration file.
log4cxx: AsyncAppender discardCount 0 pendingCountHistogram 892 604 552 428 357 302 292 271 250 232 225 211 213 198 190 188 182 183 171 167 161 149 150 145 137 135 143 116 137 110 126 116 120 110 115 93 113 107 91 95 93 100 94 84 100 88 87 77 99 64 82 77 61 69 62 74 57 63 62 56 62 52 54 49 49 39 49 49 47 45 48 38 45 39 48 39 36 33 40 30 36 30 33 28 27 31 31 30 27 29 24 25 24 26 24 25 22 18 21 18 22 19 18 15 15 18 18 12 17 20 14 15 16 14 22 13 16 17 14 18 14 15 17 14 15 17 13 16
-log4cxx: Checking file log4cxx.xml
log4cxx: Checking file log4cxx.properties
log4cxx: Checking file log4j.xml
log4cxx: Checking file log4j.properties
log4cxx: Could not find default configuration file.
log4cxx: FB: Setting primary appender to [async-testBadAppender].
log4cxx: FB: Setting backup appender to [async-memoryAppender].
log4cxx: FB: Adding logger [root].
log4cxx: FB: The following error reported: async dispatcher
log4cxx: Intentional NullPointerException
log4cxx: FB: INITIATING FALLBACK PROCEDURE.
log4cxx: FB: Searching for [async-testBadAppender] in logger [root].
log4cxx: FB: Replacing [async-testBadAppender] by [async-memoryAppender] in |ogger [root].