Skip to content

Short-lived macOS program with MultiprocessRollingFileAppender and AsyncAppender hangs upon exit with EXC_BAD_ACCESS in a worker thread #510

New issue
New issue
Open
Open
Short-lived macOS program with MultiprocessRollingFileAppender and AsyncAppender hangs upon exit with EXC_BAD_ACCESS in a worker thread#510
@RK-BFX

Description

@RK-BFX
RK-BFX
opened on Jul 14, 2025

General: I build Log4cxx from sources in macOS with LOG4CXX_MULTIPROCESS_ROLLING_FILE_APPENDER=on with all dependencies linked statically in order to avoid adding any dylib (DSO) dependencies, because it will be used in a plug-in running in an environment I have little control over.

Set-up:

  • MacMini M1, 2020; macOS Sequoia 15.5, Xcode 16.2 with its Command Line Tools;
  • iMac x86_64, 2017, macOS Ventura 13.7, Xcode 15.2 with its Command Line Tools.

Build and run:
Get all necessary sources (including the recent patch):

get-src-log4cxx.sh

#!/usr/bin/env bash

curl -LOR https://github.com/libexpat/libexpat/releases/download/R_2_7_1/expat-2.7.1.tar.xz
tar -xf expat-2.7.1.tar.xz
curl -LOR https://dlcdn.apache.org/apr/apr-1.7.6.tar.bz2
tar -xf apr-1.7.6.tar.bz2
curl -LOR https://dlcdn.apache.org/apr/apr-iconv-1.2.2.tar.bz2
tar -xf apr-iconv-1.2.2.tar.bz2
curl -LOR https://dlcdn.apache.org/apr/apr-util-1.6.3.tar.bz2
tar -xf apr-util-1.6.3.tar.bz2
curl -LOR https://dlcdn.apache.org/logging/log4cxx/1.4.0/apache-log4cxx-1.4.0.tar.gz
tar -xf apache-log4cxx-1.4.0.tar.gz
pushd apache-log4cxx-1.4.0/src/test/cpp/rolling/
curl -LOR --ssl-no-revoke https://raw.githubusercontent.com/apache/logging-log4cxx/refs/heads/master/src/test/cpp/rolling/multiprocessrollingtest.cpp
popd
chmod -R go-w .

Build Log4cxx and run its tests:

build-log4cxx.sh

#!/usr/bin/env bash

set -o errexit

BUILD_DIR=$(dirname "$(readlink -f "$BASH_SOURCE")")
INSTALL_DIR=${BUILD_DIR}/Release
mkdir -p "${INSTALL_DIR}"

cmake -S expat-2.7.1 -B .gen/expat -DCMAKE_INSTALL_PREFIX="${INSTALL_DIR}" -DEXPAT_SHARED_LIBS=OFF
cmake --build .gen/expat --target install --config Release

pushd apr-1.7.6
./configure --prefix="${INSTALL_DIR}"
make -sj
make -s install
popd
#{ No need to build apr-iconv separately
#pushd apr-iconv-1.2.2
#./configure --prefix="${INSTALL_DIR}" --with-apr="${INSTALL_DIR}"
#make -sj
#make -s install
#popd
#}
pushd apr-util-1.6.3
./configure --prefix="${INSTALL_DIR}" --with-apr="${INSTALL_DIR}" --with-apr-iconv="../apr-iconv-1.2.2" --with-iconv=no
make -sj
make -s install
popd

cmake -S apache-log4cxx-1.4.0 -B .gen/log4cxx \
      -DCMAKE_INSTALL_PREFIX="${INSTALL_DIR}" -DCMAKE_PREFIX_PATH="${INSTALL_DIR}" -DBUILD_SHARED_LIBS=off \
      -DAPR_STATIC=yes -DAPU_STATIC=yes -DBUILD_SITE=OFF -DLOG4CXX_MULTIPROCESS_ROLLING_FILE_APPENDER=ON
cmake --build .gen/log4cxx --target install --config Release --parallel
ctest --test-dir .gen/log4cxx -C Release --output-on-failure

Input the test program:

hang.cpp

#include <log4cxx/defaultconfigurator.h>
#include <log4cxx/logger.h>
#include <log4cxx/logmanager.h>

int main() {
   log4cxx::DefaultConfigurator::configure( log4cxx::LogManager::getLoggerRepository() );
   LOG4CXX_WARN( log4cxx::Logger::getRootLogger(), "Exiting");
   return 0;
}

and the configuration file:

log4cxx.xml

<log4j:configuration xmlns:log4j='http://logging.apache.org/'>

  <appender name='RollingFiles' class='org.apache.log4j.rolling.MultiprocessRollingFileAppender'>
    <rollingPolicy class='org.apache.log4j.rolling.TimeBasedRollingPolicy'>
      <param name='FileNamePattern' value="%d{yyyy}.log"/>
      <!-- Contrary to docs, the ActiveFileName option does not seem to be supported -->
    </rollingPolicy>

    <layout class='org.apache.log4j.PatternLayout'>
      <param name='ConversionPattern' value="%m%n"/>
    </layout>
  </appender>

  <appender name='Asynchronous' class='org.apache.log4j.AsyncAppender'>
    <appender-ref ref='RollingFiles'/>
  </appender>

  <root>
    <appender-ref ref='Asynchronous'/>
  </root>

</log4j:configuration>

Build and run the test:

build-n-run.sh

clang -std=c++17 -O3 -DNDEBUG -lc++ -I"Release/include" -I"Release/include/apr-1" \
      "Release/lib/liblog4cxx.a" "Release/lib/libaprutil-1.a" "Release/lib/libapr-1.a" "Release/lib/libexpat.a" \
      -o hang -- hang.cpp
for n in {0..999} ; do echo $n && ./hang 2>/dev/null ; done

Expected: all test runs finish without freezes or crashes.

Actual: the very first test run hangs (both on arm64 and on x86_64).

Thread call stacks captured by Xcode on arm64 are:

Main thread 

Thread 1 Queue : com.apple.main-thread (serial)
#0	0x000000018d20a9b8 in __ulock_wait ()
#1	0x000000018d24d0b0 in _pthread_join ()
#2	0x000000018d17ce84 in std::__1::thread::join ()
#3	0x0000000102dde8f0 in log4cxx::AsyncAppender::AsyncAppenderPriv::stopDispatcher ()
#4	0x0000000102dde7b4 in log4cxx::AsyncAppender::close ()
#5	0x0000000102dd2234 in log4cxx::helpers::AppenderAttachableImpl::removeAllAppenders ()
#6	0x0000000102e4683c in log4cxx::Logger::removeAllAppenders ()
#7	0x0000000102e22818 in log4cxx::Hierarchy::~Hierarchy ()
#8	0x0000000102e228a8 in log4cxx::Hierarchy::~Hierarchy ()
#9	0x0000000102e22904 in log4cxx::Hierarchy::~Hierarchy ()
#10	0x0000000102dd0c38 in std::__1::default_delete<log4cxx::AppenderSkeleton::AppenderSkeletonPrivate>::operator()[abi:ne180100] ()
#11	0x0000000102e2b67c in std::__1::__shared_ptr_pointer<log4cxx::Hierarchy*, std::__1::shared_ptr<log4cxx::Hierarchy>::__shared_ptr_default_delete<log4cxx::Hierarchy, log4cxx::Hierarchy>, std::__1::allocator<log4cxx::Hierarchy>>::__on_zero_shared ()
#12	0x0000000102dd5ee8 in std::__1::__shared_count::__release_shared[abi:ne180100] ()
#13	0x0000000102dd5e88 in std::__1::__shared_weak_count::__release_shared[abi:ne180100] ()
#14	0x0000000102dd5e58 in std::__1::shared_ptr<log4cxx::Level>::~shared_ptr[abi:ne180100] ()
#15	0x0000000102dd19fc in std::__1::shared_ptr<log4cxx::spi::Filter>::~shared_ptr[abi:ne180100] ()
#16	0x0000000102e0422c in log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate::~DefaultRepositorySelectorPrivate ()
#17	0x0000000102e04200 in log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate::~DefaultRepositorySelectorPrivate ()
#18	0x0000000102e041cc in std::__1::default_delete<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate>::operator()[abi:ne180100] ()
#19	0x0000000102e04188 in std::__1::unique_ptr<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate, std::__1::default_delete<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate>>::reset[abi:ne180100] ()
#20	0x0000000102e04110 in std::__1::unique_ptr<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate, std::__1::default_delete<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate>>::~unique_ptr[abi:ne180100] ()
#21	0x0000000102e03f5c in std::__1::unique_ptr<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate, std::__1::default_delete<log4cxx::spi::DefaultRepositorySelector::DefaultRepositorySelectorPrivate>>::~unique_ptr[abi:ne180100] ()
#22	0x0000000102e03f30 in log4cxx::spi::DefaultRepositorySelector::~DefaultRepositorySelector ()
#23	0x0000000102e03f94 in log4cxx::spi::DefaultRepositorySelector::~DefaultRepositorySelector ()
#24	0x0000000102dd83a0 in std::__1::__destroy_at[abi:ne180100]<log4cxx::spi::LoggingEvent, 0> ()
#25	0x0000000102e51614 in std::__1::allocator_traits<std::__1::allocator<log4cxx::spi::DefaultRepositorySelector>>::destroy[abi:ne180100]<log4cxx::spi::DefaultRepositorySelector, void, void> ()
#26	0x0000000102e515e4 in std::__1::__shared_ptr_emplace<log4cxx::spi::DefaultRepositorySelector, std::__1::allocator<log4cxx::spi::DefaultRepositorySelector>>::__on_zero_shared_impl[abi:ne180100]<std::__1::allocator<log4cxx::spi::DefaultRepositorySelector>, 0> ()
#27	0x0000000102e51464 in std::__1::__shared_ptr_emplace<log4cxx::spi::DefaultRepositorySelector, std::__1::allocator<log4cxx::spi::DefaultRepositorySelector>>::__on_zero_shared ()
#28	0x0000000102dd5ee8 in std::__1::__shared_count::__release_shared[abi:ne180100] ()
#29	0x0000000102dd5e88 in std::__1::__shared_weak_count::__release_shared[abi:ne180100] ()
#30	0x0000000102dd5e58 in std::__1::shared_ptr<log4cxx::Level>::~shared_ptr[abi:ne180100] ()
#31	0x0000000102dd19fc in std::__1::shared_ptr<log4cxx::spi::Filter>::~shared_ptr[abi:ne180100] ()
#32	0x0000000102dda8a8 in std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>::~pair ()
#33	0x0000000102dda878 in std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>::~pair ()
#34	0x0000000102dda850 in std::__1::__destroy_at[abi:ne180100]<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>, 0> ()
#35	0x0000000102dda7d8 in std::__1::allocator_traits<std::__1::allocator<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>>>::destroy[abi:ne180100]<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>, void, void> ()
#36	0x0000000102ddb498 in std::__1::vector<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>, std::__1::allocator<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>>>::__base_destruct_at_end[abi:ne180100] ()
#37	0x0000000102ddb418 in std::__1::vector<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>, std::__1::allocator<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>>>::__destruct_at_end[abi:ne180100] ()
#38	0x0000000102ddb380 in std::__1::vector<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>, std::__1::allocator<std::__1::pair<unsigned long, std::__1::shared_ptr<log4cxx::helpers::Object>>>>::pop_back ()
#39	0x0000000102ddb320 in log4cxx::helpers::APRInitializer::APRInitializerPrivate::~APRInitializerPrivate ()
#40	0x0000000102ddb2d0 in log4cxx::helpers::APRInitializer::APRInitializerPrivate::~APRInitializerPrivate ()
#41	0x0000000102ddb29c in std::__1::default_delete<log4cxx::helpers::APRInitializer::APRInitializerPrivate>::operator()[abi:ne180100] ()
#42	0x0000000102ddb258 in std::__1::unique_ptr<log4cxx::helpers::APRInitializer::APRInitializerPrivate, std::__1::default_delete<log4cxx::helpers::APRInitializer::APRInitializerPrivate>>::reset[abi:ne180100] ()
#43	0x0000000102ddb1e0 in std::__1::unique_ptr<log4cxx::helpers::APRInitializer::APRInitializerPrivate, std::__1::default_delete<log4cxx::helpers::APRInitializer::APRInitializerPrivate>>::~unique_ptr[abi:ne180100] ()
#44	0x0000000102dd8a08 in std::__1::unique_ptr<log4cxx::helpers::APRInitializer::APRInitializerPrivate, std::__1::default_delete<log4cxx::helpers::APRInitializer::APRInitializerPrivate>>::~unique_ptr[abi:ne180100] ()
#45	0x0000000102dd8aac in log4cxx::helpers::APRInitializer::~APRInitializer ()
#46	0x0000000102dd8be0 in log4cxx::helpers::APRInitializer::~APRInitializer ()
#47	0x0000000102ddb9dc in log4cxx::helpers::WideLife<log4cxx::helpers::APRInitializer>::~WideLife ()
#48	0x0000000102dd8eb0 in log4cxx::helpers::WideLife<log4cxx::helpers::APRInitializer>::~WideLife ()
#49	0x000000018d102944 in __cxa_finalize_ranges ()
#50	0x000000018d102704 in exit ()
#51	0x000000018d254dc8 in dyld4::LibSystemHelpers::exit ()
#52	0x000000018ceaacac in dyld4::LibSystemHelpersWrapper::exit ()
#53	0x000000018ceaabc8 in start ()

Worker thread 

Thread 2
#0	0x0000000102dd8f2c in log4cxx::helpers::APRInitializer::getRootPool ()
#1	0x0000000102e78f80 in log4cxx::helpers::Pool::setPool ()
#2	0x0000000102e79040 in log4cxx::helpers::Pool::getAPRPool ()
#3	0x0000000102ed1890 in log4cxx::rolling::MultiprocessRollingFileAppender::isAlreadyRolled ()
#4	0x0000000102ed1e20 in log4cxx::rolling::MultiprocessRollingFileAppender::synchronizedRollover ()
#5	0x0000000102ed2bcc in log4cxx::rolling::MultiprocessRollingFileAppender::subAppend ()
#6	0x0000000102eb0348 in log4cxx::WriterAppender::append ()
#7	0x0000000102dd6ba0 in log4cxx::AppenderSkeleton::doAppendImpl ()
#8	0x0000000102dd6924 in log4cxx::AppenderSkeleton::doAppend ()
#9	0x0000000102dd18f4 in log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders ()
#10	0x0000000102ddddc0 in log4cxx::AsyncAppender::dispatch ()
#11	0x0000000102de37b4 in std::__1::__invoke[abi:ne180100]<void (log4cxx::WriterAppender::WriterAppenderPriv::*&)(), log4cxx::FileAppender::FileAppenderPriv*&, void> ()
#12	0x0000000102de36f8 in std::__1::__thread_execute[abi:ne180100]<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (log4cxx::net::TelnetAppender::*)(), log4cxx::net::TelnetAppender*, 2ul> ()
#13	0x0000000102de342c in std::__1::__thread_proxy[abi:ne180100]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (log4cxx::AsyncAppender::*)(), log4cxx::AsyncAppender*>> ()
#14	0x000000018d24ac0c in _pthread_start ()

Instructions in the offending stack frame:

EXC_BAD_ACCESS (code=1, address=0x0)

hang`log4cxx::helpers::APRInitializer::getRootPool:
    0x102dd8f1c <+0>:  stp    x29, x30, [sp, #-0x10]!
    0x102dd8f20 <+4>:  mov    x29, sp
    0x102dd8f24 <+8>:  bl     0x102dd8cbc               ; log4cxx::helpers::APRInitializer::getInstance()
    0x102dd8f28 <+12>: bl     0x102dd0208               ; std::__1::unique_ptr<log4cxx::rolling::Action::ActionPrivate, std::__1::default_delete<log4cxx::rolling::Action::ActionPrivate>>::get[abi:ne180100]() const
->  0x102dd8f2c <+16>: ldr    x0, [x0]
    0x102dd8f30 <+20>: ldp    x29, x30, [sp], #0x10
    0x102dd8f34 <+24>: ret

Note: on x86_64 the call stacks are the same (at the source code level) and the disassembly is equivalent.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions