log4cxx: Segmentation fault in apr_pool_create_ex

Question

I need to use log4cxx for a C++ project. However I fail to understand the basic setup of this library. Here is my minimal attempt:

$ cat logger.cpp 
#include <log4cxx/logger.h>
#include <log4cxx/propertyconfigurator.h>
#include <log4cxx/helpers/properties.h>

static log4cxx::LoggerPtr ptr;

int main()
{
  log4cxx::helpers::Properties prop;
  prop.setProperty("log4j.rootLogger","DEBUG, A1");
  prop.setProperty("log4j.appender.A1","org.apache.log4j.ConsoleAppender");
  prop.setProperty("log4j.appender.A1.layout","org.apache.log4j.PatternLayout");
  prop.setProperty("log4j.appender.A1.layout.ConversionPattern","%d{ABSOLUTE} %-5p [%c] %m%n");
  log4cxx::PropertyConfigurator::configure(prop);

  ptr = log4cxx::Logger::getLogger("API");
  LOG4CXX_INFO(ptr , "test_info");
  return 0;
}

I then compile it using:

$ g++ -g -o logger logger.cpp -llog4cxx

It fails with:

$ gdb ./logger
[...]
Program received signal SIGSEGV, Segmentation fault.
0x00007ffff5f69dc9 in apr_pool_create_ex () from /lib64/libapr-1.so.0
Missing separate debuginfos, use: debuginfo-install apr-1.5.1-3.fc21.x86_64 apr-util-1.5.4-1.fc21.x86_64 cyrus-sasl-lib-2.1.26-19.fc21.x86_64 expat-2.1.0-10.fc21.x86_64 libdb-5.3.28-9.fc21.x86_64 libgcc-4.9.2-6.fc21.x86_64 libstdc++-4.9.2-6.fc21.x86_64 libuuid-2.25.2-3.fc21.x86_64 log4cxx-0.10.0-17.fc21.x86_64 nspr-4.10.8-1.fc21.x86_64 nss-3.19.1-1.0.fc21.x86_64 nss-softokn-freebl-3.19.1-1.0.fc21.x86_64 nss-util-3.19.1-1.0.fc21.x86_64 openldap-2.4.40-3.fc21.x86_64 zlib-1.2.8-7.fc21.x86_64
(gdb) bt
#0  0x00007ffff5f69dc9 in apr_pool_create_ex () from /lib64/libapr-1.so.0
#1  0x00007ffff7b26b58 in log4cxx::helpers::Pool::Pool() () from /lib64/liblog4cxx.so.10
#2  0x00007ffff7ae06ea in log4cxx::helpers::MutexException::formatMessage(int) () from /lib64/liblog4cxx.so.10
#3  0x00007ffff7ae0786 in log4cxx::helpers::MutexException::MutexException(int) () from /lib64/liblog4cxx.so.10
#4  0x00007ffff7b4a310 in log4cxx::helpers::synchronized::synchronized(log4cxx::helpers::Mutex const&) () from /lib64/liblog4cxx.so.10
#5  0x00007ffff7b5d9c8 in log4cxx::WriterAppender::close() () from /lib64/liblog4cxx.so.10
#6  0x00007ffff7ac979c in log4cxx::ConsoleAppender::~ConsoleAppender() () from /lib64/liblog4cxx.so.10
#7  0x00007ffff7ac98b9 in log4cxx::ConsoleAppender::~ConsoleAppender() () from /lib64/liblog4cxx.so.10
#8  0x00007ffff7aba247 in log4cxx::helpers::AppenderAttachableImpl::~AppenderAttachableImpl() () from /lib64/liblog4cxx.so.10
#9  0x00007ffff7b0494c in log4cxx::Logger::~Logger() () from /lib64/liblog4cxx.so.10
#10 0x00007ffff7b388b4 in log4cxx::spi::RootLogger::~RootLogger() () from /lib64/liblog4cxx.so.10
#11 0x00007ffff7b0429a in log4cxx::Logger::~Logger() () from /lib64/liblog4cxx.so.10
#12 0x00007ffff7b04429 in log4cxx::Logger::~Logger() () from /lib64/liblog4cxx.so.10
#13 0x0000000000401d6e in log4cxx::helpers::ObjectPtrT<log4cxx::Logger>::~ObjectPtrT (this=0x6031a0 <ptr>, __in_chrg=<optimized out>) at /usr/include/log4cxx/helpers/objectptr.h:100
#14 0x00007ffff6e38392 in __run_exit_handlers () from /lib64/libc.so.6
#15 0x00007ffff6e383e5 in exit () from /lib64/libc.so.6
#16 0x00007ffff6e1efe7 in __libc_start_main () from /lib64/libc.so.6
#17 0x0000000000401599 in _start ()

What is so fundamentally wrong to using a global variable for the logger ? It does make sense to me to have a singleton pattern here.

System is: Fedora 21 with:

$ rpm -qv log4cxx
log4cxx-0.10.0-17.fc21.x86_64

and:

$ g++ -v
Using built-in specs.
COLLECT_GCC=g++
COLLECT_LTO_WRAPPER=/usr/libexec/gcc/x86_64-redhat-linux/4.9.2/lto-wrapper
Target: x86_64-redhat-linux
Configured with: ../configure --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-bootstrap --enable-shared --enable-threads=posix --enable-checking=release --enable-multilib --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-gnu-unique-object --enable-linker-build-id --with-linker-hash-style=gnu --enable-languages=c,c++,objc,obj-c++,fortran,ada,go,lto --enable-plugin --enable-initfini-array --disable-libgcj --with-isl=/builddir/build/BUILD/gcc-4.9.2-20150212/obj-x86_64-redhat-linux/isl-install --with-cloog=/builddir/build/BUILD/gcc-4.9.2-20150212/obj-x86_64-redhat-linux/cloog-install --enable-gnu-indirect-function --with-tune=generic --with-arch_32=i686 --build=x86_64-redhat-linux
Thread model: posix
gcc version 4.9.2 20150212 (Red Hat 4.9.2-6) (GCC) 

Answer 1

An even more minimal attempt will crash in exactly the same way:

#include <log4cxx/logger.h>
#include <log4cxx/basicconfigurator.h>

static log4cxx::LoggerPtr ptr;

int main()
{
  log4cxx::BasicConfigurator::configure();

  ptr = log4cxx::Logger::getLogger("API");
  return 0;
}

The ultimate reasons for this silly debacle are very deep-seated, having to do with fundamental design flaws in log4cxx (starting with the misguided attempt - and philosophy - to make C++ code "look and feel and work like Java").

The proximate reason is that the destructor of the Logger held by the global LoggerPtr ptr is invoked too late. By that time, the APR library (on which the log4cxx codebase depends) will have been dismissed, and consequently the synchronized::synchronized constructor call (#4 in the stack trace) will necessarily fail - after which some kind of crash becomes inevitable. Why the code has to jump through such hoops to release resources is a saga unto itself, and not worth going into here.

The problem, as such, has to do with the order of static de-initializations: The APR library is dismissed "too early" because it's actually initialized, through a static singleton, too late (in the example code, when the LoggerPtr is actually given a Logger to hold).

The example code can be "fixed" by adding this statement before exiting main() (e.g. before the return 0;):

ptr = 0;

This will have the effect of invoking the complex resource release sequence while the APR library is still "alive".

A more general "solution" would involve controlling the lifetime of the APR library appropriately. The log4cxx codebase has static Meyers singletons scattered all over, including one to wrap calls to apr_initialize() and apr_terminate() for the APR library, but the well known "static initialization order fiasco" makes it difficult to arrange that particular singleton to be the "oldest". (It would have to be invoked from the constructors of every other singleton.) The practical "answer", therefore, is to keep the APR library alive forever, by an extra call to apr_initialize() - say, early in main() - not balanced with a matching apr_terminate(), and leaking that particular resource at program termination.

Note that the bug can be triggered in other ways. And, in fact, this bug became a show-stopper for subsequent releases, and that may be why the entire log4cxx project basically died a decade ago.