Logging class critique

Started by
10 comments, last by Dante3085 4 years, 8 months ago

I am looking for people to take a look at my Logging class and see if there are any things structure wise or anything else they would do different.

I have 3 basic approaches...
1. Log is a singleton class. You can get the instance by calling "getInstance()".
2. Log is mainly manipulated by using operator<<.  You can put in numbers, strings, objects that are loggable, LogLevels and LogOptions.
    LogOptions put predefined Input into the Log (e.g. Stacktrace) , perform predefined actions (e.g. write log to file) or put the Log into states
    in which it expects certain types of input (e.g. name of logfile).
3. The entire Log is stored in a single std::string.



/* Example usage of Log.h
   Appends a LogEntry to the Log with Warning LogLevel, a Timestamp, the message "This is a warning!" and a Stacktrace.
   This LogEntry is printed to console and written to the default logfile "stdlog.txt".
*/
Log::getInstance() << LogOption::PTC << LogLevel::WARNING << LogOption::TIMESTAMP << "This is a warning!" << LogOption::STACKTRACE
                   << LogOption::END << LogOption::WTF;

// This is the console output from main function executed in Visual Studio 2019
/*
WARNING | Wed Aug  7 13:40:09 2019 | This is a warning!
         0# boost::stacktrace::basic_stacktrace<std::allocator<boost::stacktrace::frame> >::init at C:\Programming\Libraries\boost_1_70_0\boost\stacktrace\stacktrace.hpp:75
         1# ProjectSpace::Log::operator<< at C:\Programming\Projekte\ProjectSpace\src\header\Log.h:176
         2# main at C:\Programming\Projekte\ProjectSpace\src\main.cpp:122
         3# __scrt_common_main_seh at d:\agent\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
         4# BaseThreadInitThunk in KERNEL32
         5# RtlUserThreadStart in ntdll*/


// Log.h
#pragma once

#include <string>
#include <ctime>
#include <iostream>
#include <fstream>
#include <algorithm>
#include <boost/stacktrace.hpp>

#include "Logable.h"

/*
_CRT_SECURE_NO_WARNINGS is defined because of C's Time functions.
https://docs.microsoft.com/de-de/cpp/c-runtime-library/security-features-in-the-crt?view=vs-2019

TODO: Seperate Thread for Logging ?
TODO: Write to file in destructor ? Possible IO-Exceptions.
TODO: Serialize Log Object ?
*/

namespace ProjectSpace
{
	enum class LogLevel
	{
		STATUS,  // Mark LogEntry as a Status LogEntry. Status LogEntries exist for general logging. Low priority.
		WARNING, // Mark LogEntry as Warning LogEntry. Warning LogEntries exist for issues that don't break the program, but should be looked at. Mid Priority.
		ERR      // Mark LogEntry as Error LogEntry. Error LogEntries exist for issues that break the program and need to be looked at immediately. High priority.
	};
	using ll = LogLevel;

	enum class LogOption
	{
		ENABLE,     // Enable all Logging functionality.
		DISABLE,    // Disable all Logging functionality(After disabling, LogOption::ENABLE and LogOption::DISABLE are still processed.)
		STACKTRACE, // Append Stacktrace to LogEntry.
		TIMESTAMP,  // Append Timestamp to LogEntry.
		PTC,        // Print next LogEntry to console. End of LogEntry is signaled with LogOption::END.
		END,        // Signal end of LogEntry.
		WTF,        // Write Log(Set of all LogEntries) to the LogFile.
		APPEND,     // Append to existing file contents on LogOption::WTF(Write to file).
		OVERWRITE,  // Overwrite existing file contents on LogOption::WTF(Write to file).
		FILENAME,   // Set Logfile name(i.e. Path to Logfile).
		RESET,      // Reset the Log to it's initial state(Remove all LogEntries and reset variables to their initial state.)
		CLEAR,      // Remove all LogEntries.
		EXIT        // Write log to file/Save log then exit the program. For situations when it doesn't make sense to keep the program running.
	};
	using lo = LogOption;

	class Log
	{
	public:

		static Log& getInstance()
		{
			/* Memory for singleton is only allocated on the first call of getInstance().
			 * singleton is avaible for every subsequent call of getInstance().
			*/
			static Log singleton;
			return singleton;
		}

		// Mache es unmöglich den Kopierkonstruktor aufzurufen.
		Log(Log const&) = delete;

		// Mache es unmöglich den Zuweisungsoperator aufzurufen.
		void operator=(Log const&) = delete;

		/* Appends a LogEntry with a timestamp, stacktrace, the given message and loglevel
		   and prints it to the console.
		*/
		void defaultLog(std::string const& message, LogLevel logLevel)
		{
			*this << lo::PTC << logLevel << lo::TIMESTAMP << message << lo::STACKTRACE << lo::END;
		}

		// Only allow numeric types.
		template< typename T, 
	    typename = typename std::enable_if<std::is_arithmetic<T>::value, T>::type>
		Log& operator<<(T const& t)
		{
			if (disabled)
			{
				return *this;
			}

			std::string temp = std::to_string(t);

			if (printNextEntryToConsole)
			{
				tempLogEntry.append(temp);
			}

			logString.append(temp);
			return *this;
		}

		Log& operator<<(Logable const& l)
		{
			if (disabled)
			{
				return *this;
			}

			std::string temp = l.toString();

			if (printNextEntryToConsole)
			{
				tempLogEntry.append(temp);
			}

			logString.append(temp);
			return *this;
		}

		Log& operator<<(std::string const& s)
		{
			if (disabled)
			{
				return *this;
			}

			if (setFilename)
			{
				logFileName = s;
				setFilename = false;
			}
			else
			{
				if (printNextEntryToConsole)
				{
					tempLogEntry.append(s);
				}

				logString.append(s);
			}
			return *this;
		}

		Log& operator<<(LogOption const& lo)
		{
			if (lo == LogOption::ENABLE || lo == LogOption::DISABLE)
			{
				std::string temp{};
				time_t now = time(NULL);
				temp.append(ctime(&now));
				// temp.erase(std::remove(temp.begin(), temp.end(), '\n'), temp.end());
				temp.erase(temp.size() - 1);
				temp.append(" ");

				if (lo == LogOption::ENABLE)
				{
					disabled = false;
					temp.append("Logging Enabled\n");
				}
				else if (lo == LogOption::DISABLE)
				{
					disabled = true;
					temp.append("Logging Disabled\n");
				}

				std::cout << temp;
				logString.append(temp);
			}
			else
			{
				if (disabled)
				{
					return *this;
				}

				std::string temp{};
				switch (lo)
				{
				case LogOption::STACKTRACE:
				{
					temp = boost::stacktrace::to_string(boost::stacktrace::stacktrace());
					replaceAll(temp, "\n", "\n\t");
					temp.insert(temp.begin(), '\n');
					temp.insert(temp.begin() + 1, '\t');
					temp.erase(temp.end() - 1);
					break;
				}
				case LogOption::TIMESTAMP:
				{
					time_t now = time(NULL);
					temp.append(ctime(&now));
					temp.erase(temp.size() - 1);
					temp.append(" | ");
					break;
				}
				case LogOption::PTC:
				{
					printNextEntryToConsole = true;
					break;
				}
				case LogOption::END:
				{
					if (printNextEntryToConsole)
					{
						std::cout << tempLogEntry;
						tempLogEntry.clear();
						printNextEntryToConsole = false;
					}
					break;
				}
				case LogOption::WTF:
				{
					if (appendToFile)
					{
						std::ofstream out(logFileName, std::ofstream::app);
						out << logString;
						out.close();
					}
					else
					{
						std::ofstream out(logFileName);
						out << logString;
						out.close();
					}
					break;
				}
				case LogOption::APPEND:
				{
					appendToFile = true;
					break;
				}
				case LogOption::OVERWRITE:
				{
					appendToFile = false;
					break;
				}
				case LogOption::FILENAME:
				{
					setFilename = true;
					break;
				}
				case LogOption::RESET:
				{
					logString.clear();
					disabled = false;
					printNextEntryToConsole = false;
					tempLogEntry.clear();
					appendToFile = true;
					logFileName = "stdlog.txt";
					break;
				}
				case LogOption::CLEAR:
				{
					logString.clear();
					tempLogEntry.clear();
					break;
				}
				case LogOption::EXIT:
				{
					// TODO: Log Objekt persistent speichern.

					*this << lo::PTC << lo::TIMESTAMP << "Exiting program due to unsalvageable state. Press Enter to exit...\n" << lo::END;
					std::cin.get();
					*this << lo::WTF;
					exit(1);

					break;
				}
				default:
				{
					temp.append("Unknown LogOption.");
				}
				}

				if (printNextEntryToConsole)
				{
					tempLogEntry.append(temp);
				}

				logString.append(temp);
			}
			return *this;
		}

		Log& operator<<(LogLevel const& ll)
		{
			if (disabled)
			{
				return *this;
			}

			std::string temp;
			switch (ll)
			{
			case LogLevel::STATUS:
			{
				temp.append("STATUS | ");
				break;
			}
			case LogLevel::WARNING:
			{
				temp.append("WARNING | ");
				break;
			}
			case LogLevel::ERR:
			{
				temp.append("ERROR | ");
				break;
			}
			default:
			{
				temp.append("Unknown LogLevel | ");
			}
			}

			if (printNextEntryToConsole)
			{
				tempLogEntry.append(temp);
			}

			logString.append(temp);
			return *this;
		}

	private:
		Log() : logString{ "" }, disabled{false},
			printNextEntryToConsole{ false }, tempLogEntry{""},
			appendToFile{ true }, logFileName{"stdlog.txt"},
			setFilename{false} {}

		~Log()
		{
			
		}

		std::string logString;
		bool disabled;
		bool printNextEntryToConsole;

		/* Falls nächster Logeintrag auf Konsole geprinted werden soll, muss das Ergebnis
		   der verschiedenen Stream-Operatoren als ein Logeintrag in einem string festgehalten
		   werden.
	    */
		std::string tempLogEntry;
		bool appendToFile;
		std::string logFileName;
		bool setFilename;

	private:
		// Replaces all occurences of "from" in "str" to "to".
		void replaceAll(std::string& str, std::string const& from, std::string const& to)
		{
			if (from.empty())
				return;

			size_t start_pos = 0;
			while ((start_pos = str.find(from, start_pos)) != std::string::npos)
			{
				str.replace(start_pos, from.length(), to);
				start_pos += to.length(); // In case 'to' contains 'from', like replacing 'x' with 'yx'
			}
		}
	};
}

Thanks.

Advertisement
13 hours ago, Dante3085 said:

Log is a singleton class. You can get the instance by calling "getInstance()".

Why? Singleton is an anti-pattern.

It doesn't even make sense for logging; why are you intentionally limiting yourself to one log? network, engine, input, sound... they could all be separate logs.

if you think programming is like sex, you probably haven't done much of either.-------------- - capn_midnight
6 hours ago, ChaosEngine said:

Why? Singleton is an anti-pattern.

It doesn't even make sense for logging; why are you intentionally limiting yourself to one log? network, engine, input, sound... they could all be separate logs.

I know that a lot of people have different opinions about design patterns and OO in general. That makes it quite hard as someone who is not very experinced to decide what to use and what not to use. So I just decided to try Singleton for myself and so far I experienced the global Log to be an advantage instead of being a disadvantage. I just include Log.h anywhere I need it and am able to manipulate the same Log as anyone else.

Couldn't i just implement different Logging Channels inside the Log class like Gregory Sandor stated in Game Engine Architecture (9.1.3 Channels)

I lack the experience and overview of the colleagues, so i can't say much to the pros and cons of the design patterns, only that the opinions differ :-). I too use a singleton and a central mutex protected log file, simply because i would expect it to be easier to search a single log file (with command line tools, Linux here) than to align several different files. My log is pretty informal, with just a timestamp, a source (that's probably where others would use different files), severity and the text (hints and tips welcome) ?

But, if it fits your needs and works, why not. I would naively expect that, when it comes to multitasking (edit: i mean -threading), a single logfile might have an impact on performance through excessive locking. But i am not that far yet. After all, a logging mechanism is adapted quickly, compared to other parts ...

If you are in cpp and want usefull logging, performance and stability matters. Don't use mutex or similar synchonization objects, at least not on the top level of your logging system because they can lead to your program become very slow and unresponsive if you log heavily.I know it is simple but you should consider using one buffer per thread approach.

I didn't looked at your code very close but I saw the very huge switch/case statement. This seems as if you have a design in mind that could be solved in a more generic approach but anyways.

The system I use is a little bit more complex. We use a single class approach e.g. a no-class approach as our system resides in a namespace encapsulating a set of global static functions. It is designed to the principle "don't use a class if you don't have to" first and you can define a severity and a verbosity flag on every call to the log message function.


#if defined(LOG_RUNTIME_SEVERITY_SETTINGS) && LOG_RUNTIME_SEVERITY_SETTINGS == 1
#define SEVERITY(Level) ::Log::DynamicSeverityEvaluator<Level>
#else
#define SEVERITY(Level) ::Log::StaticSeverityEvaluator<Level, LOG_DEFAULT_SEVERITY_LEVEL>
#endif

#if defined(LOG_RUNTIME_VERBOSITY_SETTINGS) && LOG_RUNTIME_VERBOSITY_SETTINGS == 1
#define VERBOSITY(Verbosity) ::Log::DynamicVerbosityEvaluator<Verbosity>
#else
#define VERBOSITY(Verbosity) ::Log::StaticVerbosityEvaluator<Verbosity, LOG_DEFAULT_VERBOSITY_MASK>
#endif

It defines 5 different functions to write a message, where one function is used under the hood and the other functions simply call that one adding an additional log severity


namespace SeverityFlags {
enum TYPE
	{
		Critical = 0x1,
		Error = 0x2,
		Warning = 0x3,
		Info = 0x4,
		Debug = 0x5
}; }

template <SeverityFlags::TYPE Flag> struct DynamicSeverityEvaluator { static inline bool Process() { return (Flag <= Log::Severity()); } };
template <SeverityFlags::TYPE Flag, int Level> struct StaticSeverityEvaluator { Constant(Flag <= Level); };
template <SeverityFlags::TYPE Flag> struct StaticSeverityEvaluator<Flag, 0> { Constant(false); };

...
  
#define FRM_LOG(...) ::Log::Message<::Log::SeverityFlags::Info, ::Log::VerbosityFlags::None>(__VA_ARGS__)
#define FRM_WARNING(...) ::Log::Message<::Log::SeverityFlags::Warning, ::Log::VerbosityFlags::None>(__VA_ARGS__)
#define FRM_ERROR(...) ::Log::Message<::Log::SeverityFlags::Error, ::Log::VerbosityFlags::None>(__VA_ARGS__)
#define FRM_CRITICAL(...) ::Log::Message<::Log::SeverityFlags::Critical, ::Log::VerbosityFlags::None>(__VA_ARGS__)

This allows some kind of global log level filtering while anything that is arithmetic greater than current log severity is hidden from the log.

The log verbosity


namespace VerbosityFlags {
enum TYPE
{
	None = 0,
	Custom = 0x20000
};}


template <VerbosityFlags::TYPE Flag> struct DynamicVerbosityEvaluator { static inline bool Process() { return ((Log::Verbosity() & Flag) == Flag); } };
template <VerbosityFlags::TYPE Flag, int Verbosity> struct StaticVerbosityEvaluator { Constant((Verbosity & Flag) == Flag); };
template <VerbosityFlags::TYPE Flag> struct StaticVerbosityEvaluator<Flag, 0> { Constant(true); };

is used a little bit different, to target certain audience. Working on a project with a huge team, anybody checks in code and anybody may write log messages. The verbosity system is used to define via certain type of ID, which logs are redirected to which user and/or department. When the game starts, a user ID and a department is generated for example from the user currently logged in at the PC.

This can also be used to define certain tab ID or anything else in a debugging tool so it is defined as a generic system of responsability.

As I mentioned, I defined the system global but as a one-buffer-per-thread approach. This means that every thread calls the logging on it's own so no other threads are interrupted. When ::Log::Message is called, the function will get a thread-ID and so look for the correct buffer in a multidimensional array. The thread-ID is defined from zero to n when the thread is created in the engine, so it is a simple O(1) lookup to ge the matching buffer.

Threads that aren't defined yet get the zero (main-)buffer so a little synchronization is necessary here.

Our buffers are defined as (mostly) lockless round-robbin concurrent queues. A message is placed in the queue from current thread until the queue is full. No memory relayouting happens here, the thread is spinning a few cycles instead and then returns false.

Then we have another thread, the message thread, that is doing nothing else except for grabbing the next element frome ach other threads queue and place it at a defined output channel or channels via callback. The callback is defined as global property of our log system and can be set dynamically during runtime. The callback target is undefined, so you can add anything and if you define a splitter, also many anything(s) .. manything ? ... whatever targets and in whatever format. So the system just handles the message and target flags but not the meta information, this is up to the log handler.

What I liked to do was connecting an UDP handler to the log system and have a remote debugging tool to find a bug in a game server.

However, this is just my approach but you might need something different. You should first define the use case of your system and what your needs are before you can ask for opinions. A generic use-case is sometimes a bad idea here

Cool. Thanks. I'll keep that in mind for later in my project.

And i like the term


DynamicVerbosityEvaluator

?

If I might, I would recommend leveraging the logging facility built in to the C++ standard library.  You end up using code proven safe through use by millions over decades, and you also save time you could use to make your game instead of reinventing something that you already have.  Note the date of that post: this is not a new situation you've just stumbled upon.

If you really need it, you can dress up the standard API with all kinds of macro hackery to add things like __LINE__ and __FILE__ or to  option out the code during release builds.  You can add thread-local storage for line buffering.

Also, logging is one of the few exceptions to the rule of no globals/singletons.

Stephen M. Webb
Professional Free Software Developer

12 hours ago, Dante3085 said:

So I just decided to try Singleton for myself and so far I experienced the global Log to be an advantage instead of being a disadvantage. I just include Log.h anywhere I need it and am able to manipulate the same Log as anyone else.

Minor point, but you don't need a singleton for that. You can just use a global instance, which then leaves open the possibility of creating other instances if the need arises.

Quote

3. The entire Log is stored in a single std::string.

I would highly recommend against this. If you have lots of logging occurring, you will run into performance problems re-allocating and copying that single string over and over. A simple approach that I've used in the past (if you need to keep log strings around and aren't flushing them to a file / elsewhere immediately) is to instead have std::deque<std::string> and push a new string every time someone performs a logging operation.

Note: I recommend a deque (not a vector) because a vector will have similar performance issues as a string when growing (need to re-allocate a larger buffer and copy); however a deque is implemented as basically a linked-list of fixed-sized arrays. Adding a new element means at worst allocating a new fixed-sized chunk and adding the new element, no copying or deallocation required.

44 minutes ago, Valakor said:

Note: I recommend a deque (not a vector) because a vector will have similar performance issues as a string when growing (need to re-allocate a larger buffer and copy)

A std::vector grows its storage exponentially (effectively doubling it on each allocation) so that it's amortized constant time.  It will also cache its allocation, so that on re-use you're probably going to have no new allocations after the first handful.  It's unlikely you'll see the vector allocation show up anywhere in your performance analysis in a typical application, except for maybe synthetic benchmarks designed to make it apparent.  I mean, go ahead and use a std::deque if you want, but there's no advantage to it if you're only ever appending at the end (push_back()) and once in a while iterating from the beginning and clearing it, and it can kill you cache to iterate it.  Your choice, but be aware of premature optimization based on cargo-cult beliefs.

Storing in many strings is more likely to require more allocations and cache hits than one big string, for the same reason.

Stephen M. Webb
Professional Free Software Developer

This topic is closed to new replies.

Advertisement