Ensure all buffered log message are written at exit (#560)

* Add FAQ answer for why buffered asynchronous output is not the default

Author: swebb2066

src/site/markdown/faq.md

@@ -22,6 +22,18 @@ Frequently Asked Technical Questions {#faq}
 -->
 [TOC]
 
+## Why doesn't Log4cxx use buffered asynchronous output by default?{#buffered_output}
+
+Being able to examine logged values is critically important during application development.
+Buffering output prevents the log file from containing the lastest messages in two situations:
+-# when a debugger stops the application at a break point
+-# when the application aborts abnormally
+(e.g. calls [std::terminate](https://en.cppreference.com/w/cpp/error/terminate.html)
+or the operating system detects a fault)
+
+Debugging a program becomes extremely confusing when the log file
+does not contain the most recently written logging requests.
+
 ## How do I add a custom level to Apache Log4cxx?{#custom_levels}
 
 This is a common topic for all the Apache logging frameworks and typically motivated to try to

src/test/cpp/fileappendertest.cpp

@@ -15,19 +15,24 @@
  * limitations under the License.
  */
 #include <log4cxx/basicconfigurator.h>
-#include <log4cxx/fileappender.h>
 #include <log4cxx/logmanager.h>
 #include <log4cxx/patternlayout.h>
 #include <log4cxx/helpers/pool.h>
 #include <log4cxx/helpers/loglog.h>
 #include <log4cxx/helpers/stringhelper.h>
+#include <log4cxx/helpers/transcoder.h>
+#include <log4cxx/helpers/fileoutputstream.h>
+#include <log4cxx/rolling/rollingfileappender.h>
+#include <log4cxx/rolling/timebasedrollingpolicy.h>
 #include "logunit.h"
 #include <apr_time.h>
+#include <apr_thread_proc.h>
+#include <fstream>
 
 using namespace log4cxx;
 using namespace log4cxx::helpers;
 
-auto getLogger(const std::string& name = std::string()) -> LoggerPtr {
+auto getLogger(const LogString& name = {}) -> LoggerPtr {
 	static struct log4cxx_initializer {
 		log4cxx_initializer() {
 			auto layout = std::make_shared<PatternLayout>(LOG4CXX_STR("%d %m%n"));
@@ -59,7 +64,9 @@ LOGUNIT_CLASS(FileAppenderTest)
 	LOGUNIT_TEST(testDirectoryCreation);
 	LOGUNIT_TEST(testgetSetThreshold);
 	LOGUNIT_TEST(testIsAsSevereAsThreshold);
-	LOGUNIT_TEST(testBufferedOutput);
+	LOGUNIT_TEST(testPeriodicFlush);
+	LOGUNIT_TEST(writeFinalBufferOutput);
+	LOGUNIT_TEST(checkFinalBufferOutput);
 	LOGUNIT_TEST_SUITE_END();
 
 #ifdef _DEBUG
@@ -119,7 +126,8 @@ LOGUNIT_CLASS(FileAppenderTest)
 		LOGUNIT_ASSERT(appender->isAsSevereAsThreshold(debug));
 	}
 
-	void testBufferedOutput()
+	// Check a file is periodically flushed
+	void testPeriodicFlush()
 	{
 		auto logger = getLogger();
 		int requiredMsgCount = 10000;
@@ -136,6 +144,8 @@ LOGUNIT_CLASS(FileAppenderTest)
 		// wait 1.2 sec and check the buffer is flushed
 		apr_sleep(1200000);
 		size_t flushedLength = file.length(p);
+
+		// Check the file extended
 		if (helpers::LogLog::isDebugEnabled())
 		{
 			LogString msg(LOG4CXX_STR("initialLength "));
@@ -146,6 +156,129 @@ LOGUNIT_CLASS(FileAppenderTest)
 		}
 		LOGUNIT_ASSERT(initialLength < flushedLength);
 	}
+
+	// Used to check the buffer is flushed at exit
+	void writeFinalBufferOutput()
+	{
+		int requiredMsgCount = 100;
+		auto logger = getLogger(LOG4CXX_STR("100message"));
+
+		// Set up a new file
+		LogString dir{ LOG4CXX_STR("output/newdir") };
+		auto writer = std::make_shared<rolling::RollingFileAppender>();
+		writer->setLayout(std::make_shared<PatternLayout>(LOG4CXX_STR("%d %m%n")));
+		writer->setFile(dir + LOG4CXX_STR("/100message.log"));
+		writer->setBufferedIO(true);
+		writer->setBufferedSeconds(1);
+		auto policy = std::make_shared<rolling::TimeBasedRollingPolicy>();
+		policy->setFileNamePattern(dir + LOG4CXX_STR("/100message-%d{yyyy}.log"));
+		writer->setRollingPolicy(policy);
+		helpers::Pool p;
+		writer->activateOptions(p);
+		logger->setAdditivity(false);
+		logger->addAppender(writer);
+
+		for ( int x = 0; x < requiredMsgCount; x++ )
+		{
+			LOG4CXX_INFO( logger, "This is test message " << x );
+		}
+	}
+
+	void checkFinalBufferOutput()
+	{
+		helpers::Pool p;
+		// start a separate instance of this to write messages to the file
+		helpers::FileOutputStream output(LOG4CXX_STR("output/newdir/100message-writer.out"), false);
+		auto thisProgram = GetExecutableFileName();
+		const char* args[] = {thisProgram.c_str(), "writeFinalBufferOutput", 0};
+		apr_procattr_t* attr = NULL;
+		setTestAttributes(&attr, output.getFilePtr(), p);
+		apr_proc_t pid;
+		startTestInstance(&pid, attr, args, p);
+
+		int exitCode;
+		apr_exit_why_e reason;
+		apr_proc_wait(&pid, &exitCode, &reason, APR_WAIT);
+		if (exitCode != 0)
+		{
+			LogString msg = LOG4CXX_STR("child exit code: ");
+			helpers::StringHelper::toString(exitCode, p, msg);
+			msg += LOG4CXX_STR("; reason: ");
+			helpers::StringHelper::toString(reason, p, msg);
+			helpers::LogLog::warn(msg);
+		}
+		LOGUNIT_ASSERT_EQUAL(exitCode, 0);
+
+		// Check all required messages are in the file
+		std::ifstream input("output/newdir/100message.log");
+		std::vector<int> messageCount;
+		int lineCount{ 0 };
+		for (std::string line; std::getline(input, line);)
+		{
+			++lineCount;
+			 auto pos = line.rfind(' ');
+			 if (line.npos != pos && pos + 1 < line.size())
+			 {
+				try
+				{
+					auto msgNumber = std::stoull(line.substr(pos));
+					if (messageCount.size() <= msgNumber)
+						messageCount.resize(msgNumber + 1);
+					++messageCount[msgNumber];
+				}
+				catch (std::exception const& ex)
+				{
+					LogString msg;
+					helpers::Transcoder::decode(ex.what(), msg);
+					msg += LOG4CXX_STR(" processing\n");
+					helpers::Transcoder::decode(line, msg);
+					helpers::LogLog::warn(msg);
+				}
+			 }
+		}
+		LogString msg = LOG4CXX_STR("lineCount: ");
+		helpers::StringHelper::toString(lineCount, p, msg);
+		helpers::LogLog::debug(msg);
+		for (auto& count : messageCount)
+			LOGUNIT_ASSERT_EQUAL(count, messageCount.front());
+	}
+
+private:
+
+	void setTestAttributes(apr_procattr_t** attr, apr_file_t* output, helpers::Pool& p)
+	{
+		if (apr_procattr_create(attr, p.getAPRPool()) != APR_SUCCESS)
+		{
+			LOGUNIT_FAIL("apr_procattr_create");
+		}
+		if (apr_procattr_cmdtype_set(*attr, APR_PROGRAM) != APR_SUCCESS)
+		{
+			LOGUNIT_FAIL("apr_procattr_cmdtype_set");
+		}
+		if (apr_procattr_child_out_set(*attr, output, NULL) != APR_SUCCESS)
+		{
+			LOGUNIT_FAIL("apr_procattr_child_out_set");
+		}
+		if (apr_procattr_child_err_set(*attr, output, NULL) != APR_SUCCESS)
+		{
+			LOGUNIT_FAIL("apr_procattr_child_err_set");
+		}
+	}
+
+	void startTestInstance(apr_proc_t* pid, apr_procattr_t* attr, const char** argv, helpers::Pool& p)
+	{
+		if (apr_proc_create(pid, argv[0], argv, NULL, attr, p.getAPRPool()) != APR_SUCCESS)
+		{
+			LOGUNIT_FAIL("apr_proc_create");
+		}
+	}
+
+	std::string GetExecutableFileName()
+	{
+		auto lsProgramFilePath = spi::Configurator::properties().getProperty(LOG4CXX_STR("PROGRAM_FILE_PATH"));
+		LOG4CXX_ENCODE_CHAR(programFilePath, lsProgramFilePath);
+		return programFilePath;
+	}
 };
 
 LOGUNIT_TEST_SUITE_REGISTRATION(FileAppenderTest);