Infinitelifetime

[vopl]

Infinite lifetime option for the runtime logger state allows to use logger during program termination phase.

[swebb2066]

These changes are currently not sufficient to allow logging during program termination phase due to other static data used in Log4cxx.

For each level there is a std::shared_ptr static variable which will be reset during the on-exit chain processing. If the Layout tries to include the level name using the (null) LevelPtr the application will crash.

Also, any LoggerPtr the application stores in a static will be reset during the on-exit chain processing. This will cause a crash if the (null) LoggerPtr is dereferenced in code to add a logging event.

[rm5248]

To Stephen's point above: once you call exit() or if you return from main(which effectively calls exit() for you), then statically allocated memory will begin to be deallocated. I'm not an expert on the C++ standard, but I think that any threads executing after you call exit() put you into the realm of undefined behavior.

The only safe way to shut down is to make sure that all of your threads are stopped before your program exits. If you don't, you will often get random crashes upon exit.

[vopl]

These changes are currently not sufficient to allow logging during program termination phase due to other static data used in Log4cxx.

Ou mama.. You are right..

For each level there is a std::shared_ptr static variable which will be reset during the on-exit chain processing. If the Layout tries to include the level name using the (null) LevelPtr the application will crash.

Also, any LoggerPtr the application stores in a static will be reset during the on-exit chain processing. This will cause a crash if the (null) LoggerPtr is dereferenced in code to add a logging event.

Ive reworked all the static-stored state, please look again. The Idea is the same, keep objects undestructed during static destruction phase.

[rm5248]

Have you tried this with the multithread test enabled? The CMake option is ENABLE_MULTITHREAD_TEST. That test should provide a decent test to see if this actually changes anything.

One potential issue is that if the objects are not destroyed, leak checking programs will return a bunch of false positives. As long as this is opt-in I'm okay with that.

[vopl]

Have you tried this with the multithread test enabled? The CMake option is ENABLE_MULTITHREAD_TEST. That test should provide a decent test to see if this actually changes anything.

Yes, the test 'multithreadtest' passes with а LOG4CXX_INFINITELIFETIME=On option.

[rm5248]

The segfault on crash is rather sporadic, you can run the following to stress it:

while [ 1 ]; do make test ARGS="-R multithreadtest"; if [ $? -ne 0 ]; then break; fi; done;

The testing that I have done does show that it works fine, without any memory leaks as I was expecting which is rather surprising to me. Some of the statics that are declared do have strings or maps in them, which do allocate memory internally, so I was expecting that memory to be leaked. I checked with both valgrind and lsan(with -fsanitize=leak). Perhaps it is not picking up on leaks that are caused by statically allocated memory.

This looks good to me; if it fixes the "my program crashes because I'm logging after calling exit()" problem with no bad side effects it sounds good to me and could be something that we enable by default. Any thoughts?

[swebb2066]

I suggest multithreadtest needs to use a layout to properly test this PR. For example

index 15ce4881..468c92ad 100644
--- a/src/test/cpp/multithreadtest.cpp
+++ b/src/test/cpp/multithreadtest.cpp
@@ -19,32 +19,29 @@

 #include <log4cxx/logger.h>
 #include <log4cxx/logmanager.h>
-#include <log4cxx/simplelayout.h>
-#include <log4cxx/appenderskeleton.h>
+#include <log4cxx/jsonlayout.h>
+#include <log4cxx/writerappender.h>
 #include <thread>
 #include <vector>
 #include <random>
 #include <mutex>

-using log4cxx::Logger;
-using log4cxx::LoggerPtr;
-using log4cxx::LogManager;
+using namespace log4cxx;

-class NullWriterAppender : public log4cxx::AppenderSkeleton
+class NullWriter : public helpers::Writer
 {
-       public:
-               NullWriterAppender() {}
-
-               virtual void close() {}
-
-               virtual bool requiresLayout() const
-               {
-                       return false;
-               }
+public:
+       void close(helpers::Pool& p) override {}
+       void flush(helpers::Pool& p) override {}
+       void write(const LogString& str, helpers::Pool& p) override {}
+};

-               virtual void append(const log4cxx::spi::LoggingEventPtr& event, log4cxx::helpers::Pool& p)
+class NullWriterAppender : public WriterAppender
+{
+       public:
+               NullWriterAppender() : WriterAppender( std::make_shared<log4cxx::JSONLayout>())
                {
-                       // Do nothing but discard the data
+                       setWriter(std::make_shared<NullWriter>());
                }
 };

[swebb2066]

This looks good to me; if it fixes the "my program crashes because I'm logging after calling exit()" problem with no bad side
effects it sounds good to me and could be something that we enable by default. Any thoughts?

@vopl could you tell us what your need is?

"logging after calling exit()" will currently produce output if the user function is added to the on-exit list after Log4cxx statics (so it is called before Log4cxx destructors are called). AFAIK the on-exit list order for module-level statics is a determined by the module placement order a link time (so it is not easily controlled). No output is produced after the APRInitialiser destructor is called. I do not think subsequent logging attempts will cause a crash as the Logger objects no longer belong to a LoggerRepository and Logger methods take an early exit.

Failing to flush buffers is the one problem with this PR that comes to mind, and this is appender/configuration dependent.

[swebb2066]

For each level there is a std::shared_ptr static variable which will be reset during the on-exit chain processing. If the Layout tries to include the level name using the (null) LevelPtr the application will crash.

This statement is incorrect and should be:

For each level there is a std::shared_ptr static variable which will be deleted during the on-exit chain processing. If the Layout tries to include the level name using the (deleted) LevelPtr the application behaviour is undefined.

The value of the raw pointer held in the std::shared_ptr is not set to nullptr in the std::shared_ptr destructor (at least for both MSVC and gcc/libstdc++-v3).

This will be preventing some crashes when logging is used after exit().

[vopl]

The segfault on crash is rather sporadic, you can run the following to stress it:

while [ 1 ]; do make test ARGS="-R multithreadtest"; if [ $? -ne 0 ]; then break; fi; done;

I see several potential places with a race condition, but I can't reproduce a crash on them in this test. And I don't see any new dangers introduced by this fix in the aspect of the 'multithread' test. In any case, I do not observe crashes under stress. If any crashes occur, could you explicitly specify the conditions for their occurrence?

[vopl]

This looks good to me; if it fixes the "my program crashes because I'm logging after calling exit()" problem with no bad side
effects it sounds good to me and could be something that we enable by default. Any thoughts?

@vopl could you tell us what your need is?

"logging after calling exit()" will currently produce output if the user function is added to the on-exit list after Log4cxx statics (so it is called before Log4cxx destructors are called). AFAIK the on-exit list order for module-level statics is a determined by the module placement order a link time (so it is not easily controlled). No output is produced after the APRInitialiser destructor is called. I do not think subsequent logging attempts will cause a crash as the Logger objects no longer belong to a LoggerRepository and Logger methods take an early exit.

I have an application whose functionality is placed in a set of .so . This functionality uses static/global objects for storing state for its internal needs, and also uses threads for code execution. I cannot ensure that the functionality stops during the program shutdown strictly before log4cxx collapses, since this functionality is extremely massive. In such conditions, I need to provide the mentioned functionals with the ability to use the logger during the destruction of the functionals themselves, which happens after exiting 'main' or with the explicit activation of 'exit', at the stage of destruction of objects with a static lifetime (while the state of the logger has already been destroyed by the same mechanism).

Attempts to use the logger (ahh.. By 'logger' I don't mean the Logger object, but the entire log4cxx functionality) in such conditions lead to a crash, for example, according to this scenario: Logger::getLogger(name) -> ... -> APRInitializer::getInstance -> using the destroyed object.

Failing to flush buffers is the one problem with this PR that comes to mind, and this is appender/configuration dependent.

Yes. That's why I don't suggest enabling the INFINITE LIFE TIME option by default.

[rm5248]

Since this is entirely opt-in and does seem to work fine, I don't have any objection to merging it in.

I can add some documentation on this option and how/when to use it unless somebody else wants to do that.

[swebb2066]

The table in cmake needs the following change:

diff --git a/src/site/markdown/development/build-cmake.md b/src/site/markdown/development/build-cmake.md
index 31f9272d..9fe9424d 100644
--- a/src/site/markdown/development/build-cmake.md
+++ b/src/site/markdown/development/build-cmake.md
@@ -71,6 +71,7 @@ $ cmake --build buildtrees/Log4cxx --target install --config Release
 |-DLOG4CXX_TEST_PROGRAM_PATH=path| An extra path to prepend to the PATH for test programs.  Log4cxx requires zip, sed, and grep on the PATH in order for the tests to work properly.                          |
 | -DPREFER_BOOST=on      | Prefer the Boost version of dependent libraries over standard library |
 | -DLOG4CXX_QT_SUPPORT=ON | Enable QString API and log4cxx::qt namespace methods, requires QtCore, choice of ON, OFF (default).                   |
+| -DLOG4CXX_EVENTS_AT_EXIT=ON | Prevent static data cleanup to allow event logging during application exit. Note: Appenders should not configure the "BufferedIO" option to true. |

 # Platform specific notes:

Is there some other documentation needed?

[rm5248]

We should probably add a bit to the threading notes page, indicating that this config option may help in unexpected exit use-cases.

[vopl]

+| -DLOG4CXX_EVENTS_AT_EXIT=ON | Prevent

@swebb2066, do you propose to rename 'INFINITELIFETIME' to 'EVENTS_AT_EXIT'?

[swebb2066]

Yes, I suggest 'EVENTS_AT_EXIT' conveys more meaning than 'INFINTELIFETIME'?

[swebb2066]

We should probably add a bit to the threading notes page, indicating that this config option may help in unexpected exit use-cases.

I suggest we add an item to the FAQ rather than threading notes page. Perhaps something like:

##Does Log4cxx support logging at process termination?
Log4cxx must be built with -DLOG4CXX_EVENTS_AT_EXIT=ON to use logging during the application termination (i.e. in static destuctors and other atexit() functions) . When this option is used, the dynamic memory deallocation, buffer flushing and file handle closing normally done in destructors is not performed. Do not set the "BufferedIO" option of any log4cxx::FileAppender to true when using this option.