path: root/linden/indra/test/llerror_tut.cpp

/** 
 * @file llerror_tut.cpp
 * @date   December 2006
 * @brief error unit tests
 *
 * $LicenseInfo:firstyear=2006&license=viewergpl$
 * 
 * Copyright (c) 2006-2008, Linden Research, Inc.
 * 
 * Second Life Viewer Source Code
 * The source code in this file ("Source Code") is provided by Linden Lab
 * to you under the terms of the GNU General Public License, version 2.0
 * ("GPL"), unless you have obtained a separate licensing agreement
 * ("Other License"), formally executed by you and Linden Lab.  Terms of
 * the GPL can be found in doc/GPL-license.txt in this distribution, or
 * online at http://secondlifegrid.net/programs/open_source/licensing/gplv2
 * 
 * There are special exceptions to the terms and conditions of the GPL as
 * it is applied to this Source Code. View the full text of the exception
 * in the file doc/FLOSS-exception.txt in this software distribution, or
 * online at http://secondlifegrid.net/programs/open_source/licensing/flossexception
 * 
 * By copying, modifying or distributing this software, you acknowledge
 * that you have read and understood your obligations described above,
 * and agree to abide by those obligations.
 * 
 * ALL LINDEN LAB SOURCE CODE IS PROVIDED "AS IS." LINDEN LAB MAKES NO
 * WARRANTIES, EXPRESS, IMPLIED OR OTHERWISE, REGARDING ITS ACCURACY,
 * COMPLETENESS OR PERFORMANCE.
 * $/LicenseInfo$
 */

#include "linden_common.h"
#include "llerror.h"

namespace
{
	void test_that_error_h_includes_enough_things_to_compile_a_message()
	{
		llinfos << "!" << llendl;
	}
}

#include <tut/tut.h>
#include "lltut.h"

#include <vector>

#include "llerrorcontrol.h"
#include "llsd.h"

namespace
{
	static bool fatalWasCalled;
	void fatalCall(const std::string&) { fatalWasCalled = true; }
	
	class TestRecorder : public LLError::Recorder
	{
	public:
		TestRecorder() : mWantsTime(false) { }
		~TestRecorder() { LLError::removeRecorder(this); }
		
		void recordMessage(LLError::ELevel level,
							const std::string& message)
		{
			mMessages.push_back(message);
		}
		
		int countMessages()			{ return (int) mMessages.size(); }
		void clearMessages()		{ mMessages.clear(); }
		
		void setWantsTime(bool t)	{ mWantsTime = t; }
		bool wantsTime()			{ return mWantsTime; }

		std::string message(int n)
		{
			std::ostringstream test_name;
			test_name << "testing message " << n << ", not enough messages";

			tut::ensure(test_name.str(), n < countMessages());
			return mMessages[n];
		}
		
	private:
		typedef std::vector<std::string> MessageVector;
		MessageVector mMessages;
		
		bool mWantsTime;
	};
}
	
namespace tut
{
	struct ErrorTestData
	{
		TestRecorder mRecorder;
		LLError::Settings* mPriorErrorSettings;
		
		ErrorTestData()
		{
			fatalWasCalled = false;
			
			mPriorErrorSettings = LLError::saveAndResetSettings();
			LLError::setDefaultLevel(LLError::LEVEL_DEBUG);
			LLError::setFatalFunction(fatalCall);
			LLError::addRecorder(&mRecorder);
		}
		
		~ErrorTestData()
		{
			LLError::removeRecorder(&mRecorder);
			LLError::restoreSettings(mPriorErrorSettings);
		}
		
		void ensure_message_count(int expectedCount)
		{
			ensure_equals("message count", mRecorder.countMessages(), expectedCount);
		}

		void ensure_message_contains(int n, const std::string& expectedText)
		{
			std::ostringstream test_name;
			test_name << "testing message " << n;

			ensure_contains(test_name.str(), mRecorder.message(n), expectedText);
		}

		void ensure_message_does_not_contain(int n, const std::string& expectedText)
		{
			std::ostringstream test_name;
			test_name << "testing message " << n;

			ensure_does_not_contain(test_name.str(), mRecorder.message(n), expectedText);
		}
	};
	
	typedef test_group<ErrorTestData>	ErrorTestGroup;
	typedef ErrorTestGroup::object		ErrorTestObject;
	
	ErrorTestGroup errorTestGroup("error");
	
	template<> template<>
	void ErrorTestObject::test<1>()
		// basic test of output
	{
		llinfos << "test" << llendl;
		llinfos << "bob" << llendl;
		
		ensure_message_contains(0, "test");
		ensure_message_contains(1, "bob");
	}
}

namespace
{
	void writeSome()
	{
		lldebugs << "one" << llendl;
		llinfos << "two" << llendl;
		llwarns << "three" << llendl;
		llerrs << "four" << llendl;
			// fatal messages write out and addtional "error" message
	}
};

namespace tut
{	
	template<> template<>
	void ErrorTestObject::test<2>()
		// messages are filtered based on default level
	{
		LLError::setDefaultLevel(LLError::LEVEL_DEBUG);
		writeSome();
		ensure_message_contains(0, "one");
		ensure_message_contains(1, "two");
		ensure_message_contains(2, "three");
		ensure_message_contains(3, "error");
		ensure_message_contains(4, "four");
		ensure_message_count(5);
	
		LLError::setDefaultLevel(LLError::LEVEL_INFO);
		writeSome();
		ensure_message_contains(5, "two");
		ensure_message_contains(6, "three");
		ensure_message_contains(7, "error");
		ensure_message_contains(8, "four");
		ensure_message_count(9);
		
		LLError::setDefaultLevel(LLError::LEVEL_WARN);
		writeSome();
		ensure_message_contains(9, "three");
		ensure_message_contains(10, "error");
		ensure_message_contains(11, "four");
		ensure_message_count(12);
		
		LLError::setDefaultLevel(LLError::LEVEL_ERROR);
		writeSome();
		ensure_message_contains(12, "error");
		ensure_message_contains(13, "four");
		ensure_message_count(14);
		
		LLError::setDefaultLevel(LLError::LEVEL_NONE);
		writeSome();
		ensure_message_count(14);
	}

	template<> template<>
	void ErrorTestObject::test<3>()
		// error type string in output
	{
		writeSome();
		ensure_message_contains(0, "DEBUG: ");
		ensure_message_contains(1, "INFO: ");
		ensure_message_contains(2, "WARNING: ");
		ensure_message_does_not_contain(3, "ERROR");
		ensure_message_contains(4, "ERROR: ");
		ensure_message_count(5);
	}

	template<> template<>
	void ErrorTestObject::test<4>()
		// file abbreviation
	{
		std::string thisFile = __FILE__;
		std::string abbreviateFile = LLError::abbreviateFile(thisFile);
		
		ensure_ends_with("file name abbreviation",
			abbreviateFile,
			"test/llerror_tut.cpp"
			);
		ensure_does_not_contain("file name abbreviation",
			abbreviateFile, "indra");
			
		std::string someFile =
#if LL_WINDOWS
			"C:/amy/bob/cam.cpp"
#else
			"/amy/bob/cam.cpp"
#endif
			;
		std::string someAbbreviation = LLError::abbreviateFile(someFile);
		
		ensure_equals("non-indra file abbreviation",
			someAbbreviation, someFile);
	}
}
	
namespace
{
	std::string locationString(int line)
	{
		std::ostringstream location;
		location << LLError::abbreviateFile(__FILE__)
				 << "(" << line << ") : ";
				 
		return location.str();
	}
	
	std::string writeReturningLocation()
	{
		llinfos << "apple" << llendl;	int this_line = __LINE__;
		return locationString(this_line);
	}
	
	std::string writeReturningLocationAndFunction()
	{
		llinfos << "apple" << llendl;	int this_line = __LINE__;
		return locationString(this_line) + __FUNCTION__;
	}
	
	std::string errorReturningLocation()
	{
		llerrs << "die" << llendl;	int this_line = __LINE__;
		return locationString(this_line);
	}
}

namespace tut
{	
	template<> template<>
	void ErrorTestObject::test<5>()
		// file and line information in log messages
	{
		std::string location = writeReturningLocation();
			// expecting default to not print location information
		
		LLError::setPrintLocation(true);
		writeReturningLocation();
		
		LLError::setPrintLocation(false);
		writeReturningLocation();
		
		ensure_message_does_not_contain(0, location);
		ensure_message_contains(1, location);
		ensure_message_does_not_contain(2, location);
	}
}

/* The following helper functions and class members all log a simple message
	from some particular function scope.  Each function takes a bool argument
	that indicates if it should log its own name or not (in the manner that
	existing log messages often do.)  The functions all return their C++
	name so that test can be substantial mechanized.
 */
 
std::string logFromGlobal(bool id)
{
	llinfos << (id ? "logFromGlobal: " : "") << "hi" << llendl;
	return "logFromGlobal";
}

static std::string logFromStatic(bool id)
{
	llinfos << (id ? "logFromStatic: " : "") << "hi" << llendl;
	return "logFromStatic";
}

namespace
{
	std::string logFromAnon(bool id)
	{
		llinfos << (id ? "logFromAnon: " : "") << "hi" << llendl;
		return "logFromAnon";
	}
}

namespace Foo {
	std::string logFromNamespace(bool id)
	{
		llinfos << (id ? "Foo::logFromNamespace: " : "") << "hi" << llendl;
		//return "Foo::logFromNamespace";
			// there is no standard way to get the namespace name, hence
			// we won't be testing for it
		return "logFromNamespace";
	}
}

namespace
{
	class ClassWithNoLogType {
	public:
		std::string logFromMember(bool id)
		{
			llinfos << (id ? "ClassWithNoLogType::logFromMember: " : "") << "hi" << llendl;
			return "ClassWithNoLogType::logFromMember";
		}
		static std::string logFromStatic(bool id)
		{
			llinfos << (id ? "ClassWithNoLogType::logFromStatic: " : "") << "hi" << llendl;
			return "ClassWithNoLogType::logFromStatic";
		}
	};
	
	class ClassWithLogType {
		LOG_CLASS(ClassWithLogType);
	public:
		std::string logFromMember(bool id)
		{
			llinfos << (id ? "ClassWithLogType::logFromMember: " : "") << "hi" << llendl;
			return "ClassWithLogType::logFromMember";
		}
		static std::string logFromStatic(bool id)
		{
			llinfos << (id ? "ClassWithLogType::logFromStatic: " : "") << "hi" << llendl;
			return "ClassWithLogType::logFromStatic";
		}
	};
	
	std::string logFromNamespace(bool id) { return Foo::logFromNamespace(id); }
	std::string logFromClassWithNoLogTypeMember(bool id) { ClassWithNoLogType c; return c.logFromMember(id); }
	std::string logFromClassWithNoLogTypeStatic(bool id) { return ClassWithNoLogType::logFromStatic(id); }
	std::string logFromClassWithLogTypeMember(bool id) { ClassWithLogType c; return c.logFromMember(id); }
	std::string logFromClassWithLogTypeStatic(bool id) { return ClassWithLogType::logFromStatic(id); }
	
	void ensure_has(const std::string& message,
		const std::string& actual, const std::string& expected)
	{
		std::string::size_type n1 = actual.find(expected);
		if (n1 == std::string::npos)
		{
			std::stringstream ss;
			ss << message << ": " << "expected to find a copy of " << expected
				<< " in actual " << actual;
			throw tut::failure(ss.str().c_str());
		}
	}
	
	typedef std::string (*LogFromFunction)(bool);
	void testLogName(TestRecorder& recorder, LogFromFunction f,
		const std::string& class_name = "")
	{
		recorder.clearMessages();
		std::string name = f(false);
		f(true);
		
		std::string messageWithoutName = recorder.message(0);
		std::string messageWithName = recorder.message(1);
		
		ensure_has(name + " logged without name",
			messageWithoutName, name);
		ensure_has(name + " logged with name",
			messageWithName, name);

		if (!class_name.empty())
		{
			ensure_has(name + "logged without name",
				messageWithoutName, class_name);
			ensure_has(name + "logged with name",
				messageWithName, class_name);
		}
	}
}

namespace tut
{
	template<> template<>
		// 	class/function information in output
	void ErrorTestObject::test<6>()
	{
		testLogName(mRecorder, logFromGlobal);
		testLogName(mRecorder, logFromStatic);
		testLogName(mRecorder, logFromAnon);
		testLogName(mRecorder, logFromNamespace);
		//testLogName(mRecorder, logFromClassWithNoLogTypeMember, "ClassWithNoLogType");
		//testLogName(mRecorder, logFromClassWithNoLogTypeStatic, "ClassWithNoLogType");
			// XXX: figure out what the exepcted response is for these
		testLogName(mRecorder, logFromClassWithLogTypeMember, "ClassWithLogType");
		testLogName(mRecorder, logFromClassWithLogTypeStatic, "ClassWithLogType");
	}
}

namespace
{
	std::string innerLogger()
	{
		llinfos << "inside" << llendl;
		return "moo";
	}
	
	std::string outerLogger()
	{
		llinfos << "outside(" << innerLogger() << ")" << llendl;
		return "bar";
	}
	
	void uberLogger()
	{
		llinfos << "uber(" << outerLogger() << "," << innerLogger() << ")" << llendl;
	}
	
	class LogWhileLogging
	{
	public:
		void print(std::ostream& out) const
		{
			llinfos << "logging" << llendl;
			out << "baz";
		}
	};

	std::ostream& operator<<(std::ostream& out, const LogWhileLogging& l)
		{ l.print(out); return out; }

	void metaLogger()
	{
		LogWhileLogging l;
		llinfos << "meta(" << l << ")" << llendl;
	}
	
}

namespace tut
{			
	template<> template<>
		// handle nested logging
	void ErrorTestObject::test<7>()
	{
		outerLogger();
		ensure_message_contains(0, "inside");
		ensure_message_contains(1, "outside(moo)");
		ensure_message_count(2);
		
		uberLogger();
		ensure_message_contains(2, "inside");
		ensure_message_contains(3, "inside");
		ensure_message_contains(4, "outside(moo)");
		ensure_message_contains(5, "uber(bar,moo)");
		ensure_message_count(6);
		
		metaLogger();
		ensure_message_contains(6, "logging");
		ensure_message_contains(7, "meta(baz)");
		ensure_message_count(8);
	}
	
	template<> template<>
		// special handling of llerrs calls
	void ErrorTestObject::test<8>()
	{
		LLError::setPrintLocation(false);
		std::string location = errorReturningLocation();
		
		ensure_message_contains(0, location + "error");
		ensure_message_contains(1, "die");
		ensure_message_count(2);
		
		ensure("fatal callback called", fatalWasCalled);
	}
}

namespace
{
	std::string roswell()
	{
		return "1947-07-08T03:04:05Z";
	}
	
	void ufoSighting()
	{
		llinfos << "ufo" << llendl;
	}
}

namespace tut
{	
	template<> template<>
		// time in output (for recorders that need it)
	void ErrorTestObject::test<9>()
	{
		LLError::setTimeFunction(roswell);

		mRecorder.setWantsTime(false);
		ufoSighting();
		ensure_message_contains(0, "ufo");
		ensure_message_does_not_contain(0, roswell());
		
		mRecorder.setWantsTime(true);
		ufoSighting();
		ensure_message_contains(1, "ufo");
		ensure_message_contains(1, roswell());
	}
	
	template<> template<>
		// output order
	void ErrorTestObject::test<10>()
	{
		LLError::setPrintLocation(true);
		LLError::setTimeFunction(roswell);
		mRecorder.setWantsTime(true);
		std::string locationAndFunction = writeReturningLocationAndFunction();
		
		ensure_equals("order is time type location function message",
			mRecorder.message(0),
			roswell() + " INFO: " + locationAndFunction + ": apple");
	}

	template<> template<>
		// multiple recorders
	void ErrorTestObject::test<11>()
	{
		TestRecorder altRecorder;
		LLError::addRecorder(&altRecorder);
		
		llinfos << "boo" << llendl;

		ensure_message_contains(0, "boo");
		ensure_equals("alt recorder count", altRecorder.countMessages(), 1);
		ensure_contains("alt recorder message 0", altRecorder.message(0), "boo");
		
		LLError::setTimeFunction(roswell);

		TestRecorder anotherRecorder;
		anotherRecorder.setWantsTime(true);
		LLError::addRecorder(&anotherRecorder);
		
		llinfos << "baz" << llendl;

		std::string when = roswell();
		
		ensure_message_does_not_contain(1, when);
		ensure_equals("alt recorder count", altRecorder.countMessages(), 2);
		ensure_does_not_contain("alt recorder message 1", altRecorder.message(1), when);
		ensure_equals("another recorder count", anotherRecorder.countMessages(), 1);
		ensure_contains("another recorder message 0", anotherRecorder.message(0), when);
	}
}

class TestAlpha
{
	LOG_CLASS(TestAlpha);
public:
	static void doDebug()	{ lldebugs << "add dice" << llendl; }
	static void doInfo()	{ llinfos  << "any idea" << llendl; }
	static void doWarn()	{ llwarns  << "aim west" << llendl; }
	static void doError()	{ llerrs   << "ate eels" << llendl; }
	static void doAll() { doDebug(); doInfo(); doWarn(); doError(); }
};

class TestBeta
{
	LOG_CLASS(TestBeta);
public:
	static void doDebug()	{ lldebugs << "bed down" << llendl; }
	static void doInfo()	{ llinfos  << "buy iron" << llendl; }
	static void doWarn()	{ llwarns  << "bad word" << llendl; }
	static void doError()	{ llerrs   << "big easy" << llendl; }
	static void doAll() { doDebug(); doInfo(); doWarn(); doError(); }
};

namespace tut
{
	template<> template<>
		// filtering by class
	void ErrorTestObject::test<12>()
	{
		LLError::setDefaultLevel(LLError::LEVEL_WARN);
		LLError::setClassLevel("TestBeta", LLError::LEVEL_INFO);
		
		TestAlpha::doAll();
		TestBeta::doAll();
		
		ensure_message_contains(0, "aim west");
		ensure_message_contains(1, "error");
		ensure_message_contains(2, "ate eels");
		ensure_message_contains(3, "buy iron");
		ensure_message_contains(4, "bad word");
		ensure_message_contains(5, "error");
		ensure_message_contains(6, "big easy");
		ensure_message_count(7);
	}
	
	template<> template<>
		// filtering by function, and that it will override class filtering
	void ErrorTestObject::test<13>()
	{
		LLError::setDefaultLevel(LLError::LEVEL_DEBUG);
		LLError::setClassLevel("TestBeta", LLError::LEVEL_WARN);
		LLError::setFunctionLevel("TestBeta::doInfo", LLError::LEVEL_DEBUG);
		LLError::setFunctionLevel("TestBeta::doError", LLError::LEVEL_NONE);
		
		TestBeta::doAll();
		ensure_message_contains(0, "buy iron");
		ensure_message_contains(1, "bad word");
		ensure_message_count(2);
	}
	
	template<> template<>
		// filtering by file
		// and that it is overridden by both class and function filtering
	void ErrorTestObject::test<14>()
	{
		LLError::setDefaultLevel(LLError::LEVEL_DEBUG);
		LLError::setFileLevel(LLError::abbreviateFile(__FILE__),
									LLError::LEVEL_WARN);
		LLError::setClassLevel("TestAlpha", LLError::LEVEL_INFO);
		LLError::setFunctionLevel("TestAlpha::doError",
									LLError::LEVEL_NONE);
		LLError::setFunctionLevel("TestBeta::doError",
									LLError::LEVEL_NONE);
		
		TestAlpha::doAll();
		TestBeta::doAll();
		ensure_message_contains(0, "any idea");
		ensure_message_contains(1, "aim west");
		ensure_message_contains(2, "bad word");
		ensure_message_count(3);
	}
	
	template<> template<>
		// proper cached, efficient lookup of filtering
	void ErrorTestObject::test<15>()
	{
		LLError::setDefaultLevel(LLError::LEVEL_NONE);

		TestAlpha::doInfo();
		ensure_message_count(0);
		ensure_equals("first check", LLError::shouldLogCallCount(), 1);
		TestAlpha::doInfo();
		ensure_message_count(0);
		ensure_equals("second check", LLError::shouldLogCallCount(), 1);

		LLError::setClassLevel("TestAlpha", LLError::LEVEL_DEBUG);
		TestAlpha::doInfo();
		ensure_message_count(1);
		ensure_equals("third check", LLError::shouldLogCallCount(), 2);
		TestAlpha::doInfo();
		ensure_message_count(2);
		ensure_equals("fourth check", LLError::shouldLogCallCount(), 2);

		LLError::setClassLevel("TestAlpha", LLError::LEVEL_WARN);
		TestAlpha::doInfo();
		ensure_message_count(2);
		ensure_equals("fifth check", LLError::shouldLogCallCount(), 3);
		TestAlpha::doInfo();
		ensure_message_count(2);
		ensure_equals("sixth check", LLError::shouldLogCallCount(), 3);
	}
	
	template<> template<>
		// configuration from LLSD
	void ErrorTestObject::test<16>()
	{
		std::string this_file = LLError::abbreviateFile(__FILE__);
		LLSD config;
		config["print-location"] = true;
		config["default-level"] = "DEBUG";
		
		LLSD set1;
		set1["level"] = "WARN";
		set1["files"][0] = this_file;
		
		LLSD set2;
		set2["level"] = "INFO";
		set2["classes"][0] = "TestAlpha";
		
		LLSD set3;
		set3["level"] = "NONE";
		set3["functions"][0] = "TestAlpha::doError";
		set3["functions"][1] = "TestBeta::doError";
		
		config["settings"][0] = set1;
		config["settings"][1] = set2;
		config["settings"][2] = set3;
		
		LLError::configure(config);
		
		TestAlpha::doAll();
		TestBeta::doAll();
		ensure_message_contains(0, "any idea");
		ensure_message_contains(0, this_file);
		ensure_message_contains(1, "aim west");
		ensure_message_contains(2, "bad word");
		ensure_message_count(3);
		
		// make sure reconfiguring works
		LLSD config2;
		config2["default-level"] = "WARN";
		
		LLError::configure(config2);
		
		TestAlpha::doAll();
		TestBeta::doAll();
		ensure_message_contains(3, "aim west");
		ensure_message_does_not_contain(3, this_file);
		ensure_message_contains(4, "error");
		ensure_message_contains(5, "ate eels");
		ensure_message_contains(6, "bad word");
		ensure_message_contains(7, "error");
		ensure_message_contains(8, "big easy");
		ensure_message_count(9);
	}
}	

/* Tests left:
	handling of classes without LOG_CLASS

	live update of filtering from file	
	
	syslog recorder
	file recorder
	cerr/stderr recorder
	fixed buffer recorder
	windows recorder

	mutex use when logging (?)
	strange careful about to crash handling (?)
*/