1

In our project we're using log4cplus indirectly: It is being used in a library that we statically link to, and that project is normally also compiled as a static lib and liked to from our executable. Everything here is Windows and Visual Studio based.

As we've been experiencing problem with application shutdown, I found that we must initialize log4cplus in our main() function, which solved the problem.

However, the application we're maintaining is - unfortunately - based on ACF (Advanced Component Framework). That means, the static lib (that links to the static lib that links to log4cplus) can be once more linked with a DLL that is then loaded by an application called Compositor during design time. (In Compositor, we can create the target application - which uses the static lib - in a high-level "component-based" fashion...). Now, the problem is that the Compositer would not close properly any more.

When it hangs after closing the main window, we can see the following callstack:

    ntdll.dll!NtWaitForAlertByThreadId() + 20 bytes Unknown
    ntdll.dll!RtlSleepConditionVariableSRW() + 265 bytes    Unknown
    KernelBase.dll!SleepConditionVariableSRW() + 45 bytes   Unknown
    msvcp140.dll!__crtSetThreadpoolWait() + 80 bytes    Unknown
    msvcp140.dll!_Cnd_timedwait() + 396 bytes   Unknown
    msvcp140.dll!_Cnd_timedwait() + 84 bytes    Unknown
    log4cplusUx64.dll!log4cplus::helpers::getFileInfo() + 3473 bytes    Unknown
    log4cplusUx64.dll!00007ff86917fefb()    Unknown
    ucrtbase.dll!_execute_onexit_table() + 342 bytes    Unknown
    ucrtbase.dll!_execute_onexit_table() + 123 bytes    Unknown
    ucrtbase.dll!_execute_onexit_table() + 52 bytes Unknown
    log4cplusUx64.dll!log4cplus::helpers::getFormattedTime() + 5056 bytes   Unknown
    log4cplusUx64.dll!log4cplus::helpers::getFormattedTime() + 5364 bytes   Unknown
    ntdll.dll!RtlAnsiStringToUnicodeString() + 663 bytes    Unknown
    ntdll.dll!LdrShutdownProcess() + 300 bytes  Unknown
    ntdll.dll!RtlExitUserProcess() + 173 bytes  Unknown
    kernel32.dll!ExitProcess() + 10 bytes   Unknown
    ucrtbase.dll!exit() + 468 bytes Unknown
    ucrtbase.dll!exit() + 127 bytes Unknown
>   Compositor.exe!__scrt_common_main_seh() Line 295    C++

In order to make Compositor close properly, I intorduced a DllMain function:

BOOL WINAPI DllMain(HINSTANCE, DWORD fdwReason, LPVOID)
{
    switch (fdwReason)
    {
    case DLL_PROCESS_ATTACH:
        log4cplus::initialize();
        break;
    case DLL_THREAD_ATTACH:
        break;
    case DLL_THREAD_DETACH:
        log4cplus::threadCleanup();
        break;
    case DLL_PROCESS_DETACH:
        log4cplus::Logger::shutdown();
        log4cplus::deinitialize();
        break;
    }
    return TRUE;
}

Now, the application would no longer start but hang at the call to log4cplus::initialize():

    ntdll.dll!NtWaitForAlertByThreadId() + 20 bytes Unknown
    ntdll.dll!RtlSleepConditionVariableSRW() + 265 bytes    Unknown
    KernelBase.dll!SleepConditionVariableSRW() + 45 bytes   Unknown
    msvcp140.dll!__crtSetThreadpoolWait() + 80 bytes    Unknown
    msvcp140.dll!_Cnd_timedwait() + 396 bytes   Unknown
    msvcp140.dll!_Cnd_timedwait() + 84 bytes    Unknown
    log4cplusUx64.dll!00007ff8697360d0()    Unknown
    log4cplusUx64.dll!00007ff86973625f()    Unknown
    log4cplusUx64.dll!log4cplus::spi::FactoryRegistry<log4cplus::spi::LocaleFactory>::FactoryRegistry<log4cplus::spi::LocaleFactory>() + 1438 bytes Unknown
    log4cplusUx64.dll!log4cplus::initialize() + 194 bytes   Unknown
>   MePiaPck.arp!DllMain(HINSTANCE__ * __formal, unsigned long fdwReason, void * __formal) Line 46  C++

If I remove that call, startup is normal but the hanging behavior, i.e. Compositer not closing, remains, regardless of threadCleanup(), Logger::shutdown() and deinitialize() (I've tried all combinations).

How can I shutdown log4cplus in a DLL so that the application can terminate properly?

Matz
  • 583
  • 1
  • 6
  • 21
  • 1
    I can understand the urge to downvote when seeing ACF mentioned... – Matz Mar 11 '20 at 14:47
  • 1
    who is write `log4cplusUx64.dll` ? here exist some global object which hung in destructor (this is show your first call stack - will be more useful if you use pdb symbols). why you not use `DllMain` from *globalinit.cxx* ? read comments in `thread_callback`. however clear visible that this dll code design only for case when dll loaded at process startup (not via LoadLibrary) and never unloaded. `initialize()` and `deinitialize();` not design to run from loader lock. possible solution create 2 exported functions for init/deinit and call it from exe at begin and end of main. – RbMm Mar 17 '20 at 20:12
  • Took me a while to decipher your comment.. Thanks, I'll try your final suggestion, although my goal was to _not_ touch the Compositer code - not even sure I'm allowed. – Matz Mar 20 '20 at 11:34
  • 1
    from fast look for log4cplus src code i understand that `log4cplus::initialize()` not design to execute inside loader lock - it deadlock here. also `deinitialize()` not design too. from your callstack i view you have some global object in `log4cplusUx64.dll` and it destructor deadlock (maybe it called `deinitialize()` - you need use pdb symbols and callstack with it - will be more informative). as solution need have exported functions in dll and call initialize/deinitialize from it and have no global objects in dll which call `deinitialize` in destructor – RbMm Mar 20 '20 at 11:54
  • @Matz I'm currently evaluating ACF (Advanced Component Framework). There is very little information online. Could you please share some of your experience with it? – Roman Byshko Sep 13 '20 at 16:56

1 Answers1

1

As it has been mentioned in @RbMm's comments, the reason why initializing log4cplus in DllMain does not work is that this function is executed inside the "loader lock" - cf. here or here.

The solution is to find a function in the DLL that is executed from the loading application's main thread, and initialize log4cplus there.

In case of ACF's Compositor, it is the package export function that is called first. Normally, it is wrapped as a macro in ACF packages, i.e. I_EXPORT_PACKAGE. Unrolling that macro allows for entering the following code:

extern "C" I_FUNCTION_EXPORT icomp::CPackageStaticInfo* I_PACKAGE_EXPORT_FUNCTION()
{
    static bool bFirstLoad = true;
    if (bFirstLoad)
    {
        log4cplus::initialize();
        log4cplus::deinitialize();
        bFirstLoad = false;
    }
    return &packageInfo;
}

Initializing and deinitializing log4cplus at the first call into the package enables the Compositor application to close and terminate normally again.

Matz
  • 583
  • 1
  • 6
  • 21
  • 1
    Thank you for answering your own question once you found the information! For me the important thing I needed to do was add atexit([](){log4cplus::deinitialize();}) to the main() function so that it is called no matter how the program exits. I also called log4cplus::initialize() as the first line of the main() functon. FYI atexit() is defined in . – Captain Normal Jan 28 '21 at 13:54