[boost] [logging] flush_log_cache doesn't flush everything?

21 Jun 2005

      I'm not sure I understand correctly, but it appears that flush_log_cache 
in the logging library doesn't actually force everything in the pipeline 
to be written by the logging thread to be written. Empirically, it seems 
that I had to add a sleep to the end of my program to cause everything 
to be written. Code-review-wise, and here I'm pretty sure I don't 
completely understand, it appears that flush_log_cache pushes things 
further down the pipeline but doesn't actually synchronize (wait for) 
the writing thread to complete. It seems like there maybe should be some 
kind of routine that "blocks" until all pending writes are complete, 
maybe just a wrapper around the ability to request the writing thread to 
finish, and then wait for it to complete. Maybe this mechanism is 
already present? I suppose that brings up other complications, such as 
what if some other thread logs something after we've asked it to stop.

In the code I was testing, I had a ts_appender, to which I added a 
appender_array, to which I added 4 write_to_files. For ~ 10 seconds I 
wrote to the log. Then I call flush_log_cache. If I don't then sleep a 
few seconds, the files are not all identical.

<?xml version="1.0" encoding="Windows-1252"?>
<VisualStudioProject
	ProjectType="Visual C++"
	Version="7.10"
	Name="LogFlushTest"
	ProjectGUID="{E0693D56-29D0-435D-BB13-8DED291C84AE}"
	Keyword="Win32Proj">
	<Platforms>
		<Platform
			Name="Win32"/>
	</Platforms>
	<Configurations>
		<Configuration
			Name="Debug|Win32"
			OutputDirectory="Debug"
			IntermediateDirectory="Debug"
			ConfigurationType="1"
			CharacterSet="2">
			<Tool
				Name="VCCLCompilerTool"
				Optimization="0"
				AdditionalIncludeDirectories="$(BOOST_ROOT)"
				PreprocessorDefinitions="WIN32;_DEBUG;_CONSOLE"
				MinimalRebuild="TRUE"
				BasicRuntimeChecks="3"
				RuntimeLibrary="1"
				UsePrecompiledHeader="0"
				WarningLevel="3"
				Detect64BitPortabilityProblems="TRUE"
				DebugInformationFormat="4"/>
			<Tool
				Name="VCCustomBuildTool"/>
			<Tool
				Name="VCLinkerTool"
				OutputFile="$(OutDir)/LogFlushTest.exe"
				LinkIncremental="2"
				AdditionalLibraryDirectories=""$(BOOST_ROOT)\bin\boost\libs\thread\build\libboost_thread.lib\vc-7_1\debug\runtime-link-static\threading-multi";"$(BOOST_ROOT)\bin\boost\libs\log\build\libboost_log.lib\vc-7_1\debug\runtime-link-static\threading-multi";"$(BOOST_ROOT)\bin\boost\libs\program_options\build\libboost_program_options.lib\vc-7_1\debug\runtime-link-static\threading-multi";"$(BOOST_ROOT)\bin\boost\libs\log\build\libboost_log.lib\vc-7_1\debug\runtime-link-static";"$(BOOST_ROOT)\bin\boost\libs\program_options\build\libboost_program_options.lib\vc-7_1\debug\runtime-link-static";"$(BOOST_ROOT)\bin";"$(BOOST_ROOT)\bin\boost";"$(BOOST_ROOT)\bin\boost\libs""
				GenerateDebugInformation="TRUE"
				ProgramDatabaseFile="$(OutDir)/LogFlushTest.pdb"
				SubSystem="1"
				TargetMachine="1"/>
			<Tool
				Name="VCMIDLTool"/>
			<Tool
				Name="VCPostBuildEventTool"/>
			<Tool
				Name="VCPreBuildEventTool"/>
			<Tool
				Name="VCPreLinkEventTool"/>
			<Tool
				Name="VCResourceCompilerTool"/>
			<Tool
				Name="VCWebServiceProxyGeneratorTool"/>
			<Tool
				Name="VCXMLDataGeneratorTool"/>
			<Tool
				Name="VCWebDeploymentTool"/>
			<Tool
				Name="VCManagedWrapperGeneratorTool"/>
			<Tool
				Name="VCAuxiliaryManagedWrapperGeneratorTool"/>
		</Configuration>
		<Configuration
			Name="Release|Win32"
			OutputDirectory="Release"
			IntermediateDirectory="Release"
			ConfigurationType="1"
			CharacterSet="2">
			<Tool
				Name="VCCLCompilerTool"
				PreprocessorDefinitions="WIN32;NDEBUG;_CONSOLE"
				RuntimeLibrary="4"
				UsePrecompiledHeader="3"
				WarningLevel="3"
				Detect64BitPortabilityProblems="TRUE"
				DebugInformationFormat="3"/>
			<Tool
				Name="VCCustomBuildTool"/>
			<Tool
				Name="VCLinkerTool"
				OutputFile="$(OutDir)/LogFlushTest.exe"
				LinkIncremental="1"
				GenerateDebugInformation="TRUE"
				SubSystem="1"
				OptimizeReferences="2"
				EnableCOMDATFolding="2"
				TargetMachine="1"/>
			<Tool
				Name="VCMIDLTool"/>
			<Tool
				Name="VCPostBuildEventTool"/>
			<Tool
				Name="VCPreBuildEventTool"/>
			<Tool
				Name="VCPreLinkEventTool"/>
			<Tool
				Name="VCResourceCompilerTool"/>
			<Tool
				Name="VCWebServiceProxyGeneratorTool"/>
			<Tool
				Name="VCXMLDataGeneratorTool"/>
			<Tool
				Name="VCWebDeploymentTool"/>
			<Tool
				Name="VCManagedWrapperGeneratorTool"/>
			<Tool
				Name="VCAuxiliaryManagedWrapperGeneratorTool"/>
		</Configuration>
	</Configurations>
	<References>
	</References>
	<Files>
		<Filter
			Name="Source Files"
			Filter="cpp;c;cxx;def;odl;idl;hpj;bat;asm;asmx"
			UniqueIdentifier="{4FC737F1-C7A5-4376-A066-2A32D752A2FF}">
			<File
				RelativePath=".\LogFlushTest.cpp">
			</File>
		</Filter>
		<Filter
			Name="Header Files"
			Filter="h;hpp;hxx;hm;inl;inc;xsd"
			UniqueIdentifier="{93995380-89BD-4b04-88EB-625FBE52EBFB}">
		</Filter>
		<Filter
			Name="Resource Files"
			Filter="rc;ico;cur;bmp;dlg;rc2;rct;bin;rgs;gif;jpg;jpeg;jpe;resx"
			UniqueIdentifier="{67DA6AB6-F800-4c08-8B7A-83BB121AAD01}">
		</Filter>
		<File
			RelativePath=".\ReadMe.txt">
		</File>
	</Files>
	<Globals>
	</Globals>
</VisualStudioProject>

//	set environment variable BOOST_ROOT to point to your top level boost directory
//	(for example mine points to e:\C++\Boost\boost_1_32_0). 

#include "windows.h"
#include <iostream>
#include <iterator>
#include <boost/bind.hpp>
#include <boost/function.hpp>
#include <boost/ref.hpp>
//#include <boost/signals.hpp>
#include <boost/tuple/tuple.hpp>
#include <list>
#include <functional>
#include <fstream>
#include <boost/log/log.hpp>
#include <boost/log/functions.hpp>
#include <boost/log/functions_ts.hpp>
using namespace std;
using namespace boost;
using namespace boost::logging;

void write_to_cout(const std::string &, const std::string &msg) { std::cout << msg; }

DWORD WINAPI ThreadProc1(LPVOID lpParameter)
{
	logger* l_pLogger = (logger*) lpParameter;

	DWORD l_dwEndTick = GetTickCount() + 5000;
	DWORD l_dwThreadID = GetCurrentThreadId();
	static DWORD s_dwI = 0;
	static s_dwTIdx = 0;
	DWORD l_dwTIdx = ++s_dwTIdx;
	DWORD l_dwI = 0;
	while(GetTickCount() < l_dwEndTick)
	{
		l_dwI++;
		s_dwI++;
		BOOST_SCOPEDLOG(*l_pLogger) << "TID: " <<  l_dwThreadID << " (" << l_dwTIdx << "/" << s_dwTIdx << " i:" << l_dwI << " s:" << s_dwI << " abcdefghijklmnopqrstuvwxyz" << endl;
	}
	BOOST_SCOPEDLOG(*l_pLogger) << "TID: " <<  l_dwThreadID << " (" << l_dwTIdx << "/" << s_dwTIdx << " done" << endl;
	flush_log_cache();
	--s_dwTIdx;
	return 0;
}

void ThreadTest(logger& rLogger, DWORD dwThreads, DWORD dwPostSleep)
{
	BOOST_SCOPEDLOG(rLogger) << "Starting Thread test shortly for " << rLogger.name() << "..." << endl;
	Sleep(3000);
	list<HANDLE> l_l;
	for(DWORD i = 0; i < dwThreads; ++i)
	{
		DWORD l_dw = 0;
		HANDLE l_h = CreateThread(NULL, 0, ThreadProc1, &rLogger, 0, &l_dw);
		l_l.push_back(l_h);
	}
	while(l_l.begin() != l_l.end())
	{
		HANDLE l_h = *l_l.begin();
		WaitForSingleObject(l_h, INFINITE);
		l_l.pop_front();
	}
	BOOST_SCOPEDLOG(rLogger) << "Thread test for " << rLogger.name() << " done." << endl;	
}

int main(int argc, char* argv[])
{
	set_log_caching(true);
	logger l_lgArray("lgArray");
	logger l_lgCout("lgCout");
	add_appender("lgCout", write_to_cout);

	add_appender("lgArray",
		ts_appender(
			appender_array()
				.add(write_to_file("btArrayFile1.txt"))
				.add(write_to_file("btArrayFile2.txt"))
				.add(write_to_file("btArrayFile3.txt"))
				.add(write_to_file("btArrayFile4.txt"))));
	ThreadTest(l_lgArray, 1, 20000); 
	flush_log_cache();

	//If these sleeps aren't included, the btArrayFiles 
	//are not all equal. 
	for(int i = 0; i < 10; ++i)
	{
		Sleep(1000);
		BOOST_SCOPEDLOG(l_lgCout) << " " << i;
	}
	BOOST_SCOPEDLOG(l_lgCout) << endl;

	return 0;
}

[boost] [logging] flush_log_cache doesn't flush everything?

Andy Schweitzer