Replaced Boost.Log with small custom logger

Boost.Log is a complex monstrosity and I can't get it to build on OS X.

CMakeLists.txt

@@ -36,10 +36,6 @@ elseif("${CMAKE_CXX_COMPILER_ID}" STREQUAL "MSVC")
 	set(enableWarningsFlags "/W4")
 	set(disableWarningsFlags "/W0")
 	
-	# Disable warning C4714: function '...' marked as __forceinline not inlined
-	# This is caused by Boost.Log
-	set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} /wd4714")
-	
 	# Disable warning C4456: declaration of '...' hides previous local declaration
 	# I'm doing that on purpose.
 	set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} /wd4458")
@@ -54,7 +50,7 @@ set_property(GLOBAL PROPERTY USE_FOLDERS ON)
 set(Boost_USE_STATIC_LIBS ON) # Use static libs
 set(Boost_USE_MULTITHREADED ON) # Enable multithreading support
 set(Boost_USE_STATIC_RUNTIME ON) # Use static C++ runtime
-find_package(Boost REQUIRED COMPONENTS filesystem locale system log date_time thread chrono)
+find_package(Boost REQUIRED COMPONENTS filesystem locale system)
 include_directories(SYSTEM ${Boost_INCLUDE_DIRS})
 
 # ... C++ Format

src/Exporter.cpp

@@ -3,6 +3,7 @@
 #include <vector>
 #include <boost/property_tree/ptree.hpp>
 #include <boost/property_tree/xml_parser.hpp>
+#include <tools.h>
 
 using std::string;
 using boost::property_tree::ptree;

src/audio/voiceActivityDetection.cpp

@@ -48,7 +48,7 @@ Timeline<bool> detectVoiceActivity(std::unique_ptr<AudioStream> audioStream) {
 
 	// Log
 	for (const auto& element : activity) {
-		logTimedEvent("utterance", static_cast<TimeRange>(element), std::string());
+		logging::logTimedEvent("utterance", static_cast<TimeRange>(element), std::string());
 	}
 
 	return activity;

src/logging.cpp

@@ -1,123 +1,131 @@
 #include "logging.h"
-#include <boost/log/sinks/unlocked_frontend.hpp>
-#include <boost/log/sinks/text_file_backend.hpp>
-#include <boost/log/sinks/sync_frontend.hpp>
-#include <boost/log/expressions.hpp>
-#include <boost/log/keywords/file_name.hpp>
-#include <boost/log/utility/setup/common_attributes.hpp>
-// ReSharper disable once CppUnusedIncludeDirective
-#include <boost/log/support/date_time.hpp>
-#include <Timed.h>
+#include <tools.h>
+#include <iostream>
 
+using namespace logging;
 using std::string;
-using std::lock_guard;
-using boost::log::sinks::text_ostream_backend;
-using boost::log::record_view;
-using boost::log::sinks::unlocked_sink;
 using std::vector;
 using std::tuple;
 using std::make_tuple;
-
-namespace expr = boost::log::expressions;
-namespace keywords = boost::log::keywords;
-namespace sinks = boost::log::sinks;
-namespace attr = boost::log::attributes;
+using std::shared_ptr;
+using std::lock_guard;
 
 template <>
-const string& getEnumTypeName<LogLevel>() {
+const string& getEnumTypeName<Level>() {
 	static const string name = "LogLevel";
 	return name;
 }
 
 template <>
-const vector<tuple<LogLevel, string>>& getEnumMembers<LogLevel>() {
-	static const vector<tuple<LogLevel, string>> values = {
-		make_tuple(LogLevel::Trace,		"Trace"),
-		make_tuple(LogLevel::Debug,		"Debug"),
-		make_tuple(LogLevel::Info,		"Info"),
-		make_tuple(LogLevel::Warning,	"Warning"),
-		make_tuple(LogLevel::Error,		"Error"),
-		make_tuple(LogLevel::Fatal,		"Fatal")
+const vector<tuple<Level, string>>& getEnumMembers<Level>() {
+	static const vector<tuple<Level, string>> values = {
+		make_tuple(Level::Trace,	"Trace"),
+		make_tuple(Level::Debug,	"Debug"),
+		make_tuple(Level::Info,		"Info"),
+		make_tuple(Level::Warn,		"Warn"),
+		make_tuple(Level::Error,	"Error"),
+		make_tuple(Level::Fatal,	"Fatal")
 	};
 	return values;
 }
 
-std::ostream& operator<<(std::ostream& stream, LogLevel value) {
+std::ostream& operator<<(std::ostream& stream, Level value) {
 	return stream << enumToString(value);
 }
 
-std::istream& operator>>(std::istream& stream, LogLevel& value) {
+std::istream& operator>>(std::istream& stream, Level& value) {
 	string name;
 	stream >> name;
-	value = parseEnum<LogLevel>(name);
+	value = parseEnum<Level>(name);
 	return stream;
 }
 
-PausableBackendAdapter::PausableBackendAdapter(boost::shared_ptr<text_ostream_backend> backend) :
-	backend(backend) {}
-
-PausableBackendAdapter::~PausableBackendAdapter() {
-	resume();
+Entry::Entry(Level level, const string& message) :
+	level(level),
+	message(message)
+{
+	time(&timestamp);
 }
 
-void PausableBackendAdapter::consume(const record_view& recordView, const string message) {
-	lock_guard<std::mutex> lock(mutex);
-	if (isPaused) {
-		buffer.push_back(std::make_tuple(recordView, message));
-	} else {
-		backend->consume(recordView, message);
+string SimpleConsoleFormatter::format(const Entry& entry) {
+	return fmt::format("[{0}] {1}", entry.level, entry.message);
+}
+
+string SimpleFileFormatter::format(const Entry& entry) {
+	return fmt::format("[{0}] {1}", formatTime(entry.timestamp, "%F %H:%M:%S"), consoleFormatter.format(entry));
+}
+
+LevelFilter::LevelFilter(shared_ptr<Sink> innerSink, Level minLevel) :
+	innerSink(innerSink),
+	minLevel(minLevel)
+{}
+
+void LevelFilter::receive(const Entry& entry) {
+	if (entry.level >= minLevel) {
+		innerSink->receive(entry);
 	}
 }
 
-void PausableBackendAdapter::pause() {
-	lock_guard<std::mutex> lock(mutex);
-	isPaused = true;
+StreamSink::StreamSink(shared_ptr<std::ostream> stream, shared_ptr<Formatter> formatter) :
+	stream(stream),
+	formatter(formatter)
+{}
+
+void StreamSink::receive(const Entry& entry) {
+	string line = formatter->format(entry);
+	*stream << line << std::endl;
 }
 
-void PausableBackendAdapter::resume() {
+StdErrSink::StdErrSink(shared_ptr<Formatter> formatter) :
+	StreamSink(std::shared_ptr<std::ostream>(&std::cerr, [](void*){}), formatter)
+{}
+
+PausableSink::PausableSink(shared_ptr<Sink> innerSink) :
+	innerSink(innerSink)
+{}
+
+void PausableSink::receive(const Entry& entry) {
+	lock_guard<std::mutex> lock(mutex);
+	if (isPaused) {
+		buffer.push_back(entry);
+	} else {
+		innerSink->receive(entry);
+	}
+}
+
+void PausableSink::pause() {
+	lock_guard<std::mutex> lock(mutex);
+	isPaused = true;
+
+}
+
+void PausableSink::resume() {
 	lock_guard<std::mutex> lock(mutex);
 	isPaused = false;
-	for (const auto& tuple : buffer) {
-		backend->consume(std::get<record_view>(tuple), std::get<string>(tuple));
+	for (const Entry& entry : buffer) {
+		innerSink->receive(entry);
 	}
 	buffer.clear();
 }
 
-BOOST_LOG_GLOBAL_LOGGER_INIT(globalLogger, LoggerType) {
-	LoggerType logger;
-
-	logger.add_attribute("TimeStamp", attr::local_clock());
-
-	return logger;
+std::mutex& getLogMutex() {
+	static std::mutex mutex;
+	return mutex;
 }
 
-BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", LogLevel)
-
-boost::shared_ptr<PausableBackendAdapter> addPausableStderrSink(LogLevel minLogLevel) {
-	// Create logging backend that logs to stderr
-	auto streamBackend = boost::make_shared<text_ostream_backend>();
-	streamBackend->add_stream(boost::shared_ptr<std::ostream>(&std::cerr, [](std::ostream*) {}));
-	streamBackend->auto_flush(true);
-
-	// Create an adapter that allows us to pause, buffer, and resume log output
-	auto pausableAdapter = boost::make_shared<PausableBackendAdapter>(streamBackend);
-
-	// Create a sink that feeds into the adapter
-	auto sink = boost::make_shared<unlocked_sink<PausableBackendAdapter>>(pausableAdapter);
-	sink->set_formatter(expr::stream << "[" << severity << "] " << expr::smessage);
-	sink->set_filter(severity >= minLogLevel);
-	boost::log::core::get()->add_sink(sink);
-
-	return pausableAdapter;
+vector<shared_ptr<Sink>>& getSinks() {
+	static vector<shared_ptr<Sink>> sinks;
+	return sinks;
 }
 
-void addFileSink(const boost::filesystem::path& logFilePath, LogLevel minLogLevel) {
-	auto textFileBackend = boost::make_shared<sinks::text_file_backend>(
-		keywords::file_name = logFilePath.string());
-	auto sink = boost::make_shared<sinks::synchronous_sink<sinks::text_file_backend>>(textFileBackend);
-	sink->set_formatter(expr::stream
-		<< "[" << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%Y-%m-%d %H:%M:%S")
-		<< "] [" << severity << "] " << expr::smessage);
-	sink->set_filter(severity >= minLogLevel);
-	boost::log::core::get()->add_sink(sink);
+void logging::addSink(shared_ptr<Sink> sink) {
+	lock_guard<std::mutex> lock(getLogMutex());
+	getSinks().push_back(sink);
+}
+
+void logging::log(Level level, const string& message) {
+	lock_guard<std::mutex> lock(getLogMutex());
+	for (auto& sink : getSinks()) {
+		sink->receive(Entry(level, message));
+	}
 }

src/logging.h

@@ -1,86 +1,145 @@
 #pragma once
 
-#include <boost/log/common.hpp>
-#include <boost/log/sinks/basic_sink_backend.hpp>
-#include <boost/log/sinks/frontend_requirements.hpp>
-#include <boost/log/sinks/text_ostream_backend.hpp>
 #include <string>
 #include <vector>
 #include <mutex>
 #include <tuple>
-#include "centiseconds.h"
-#include <boost/filesystem.hpp>
-#include "tools.h"
 #include "enumTools.h"
+#include "tools.h"
 #include "Timed.h"
 
-enum class LogLevel {
-	Trace,
-	Debug,
-	Info,
-	Warning,
-	Error,
-	Fatal,
-	EndSentinel
-};
+namespace logging {
+
+	enum class Level {
+		Trace,
+		Debug,
+		Info,
+		Warn,
+		Error,
+		Fatal,
+		EndSentinel
+	};
+
+}
 
 template<>
-const std::string& getEnumTypeName<LogLevel>();
+const std::string& getEnumTypeName<logging::Level>();
 
 template<>
-const std::vector<std::tuple<LogLevel, std::string>>& getEnumMembers<LogLevel>();
+const std::vector<std::tuple<logging::Level, std::string>>& getEnumMembers<logging::Level>();
 
-std::ostream& operator<<(std::ostream& stream, LogLevel value);
+std::ostream& operator<<(std::ostream& stream, logging::Level value);
 
-std::istream& operator>>(std::istream& stream, LogLevel& value);
+std::istream& operator>>(std::istream& stream, logging::Level& value);
 
-using LoggerType = boost::log::sources::severity_logger_mt<LogLevel>;
+namespace logging {
 
-BOOST_LOG_GLOBAL_LOGGER(globalLogger, LoggerType)
+	struct Entry {
+		Entry(Level level, const std::string& message);
 
-#define LOG(level) \
-	BOOST_LOG_STREAM_WITH_PARAMS(globalLogger::get(), (::boost::log::keywords::severity = level))
+		time_t timestamp;
+		Level level;
+		std::string message;
+	};
 
-#define LOG_TRACE LOG(LogLevel::Trace)
-#define LOG_DEBUG LOG(LogLevel::Debug)
-#define LOG_INFO LOG(LogLevel::Info)
-#define LOG_WARNING LOG(LogLevel::Warning)
-#define LOG_ERROR LOG(LogLevel::Error)
-#define LOG_FATAL LOG(LogLevel::Fatal)
+	class Formatter {
+	public:
+		virtual ~Formatter() = default;
+		virtual std::string format(const Entry& entry) = 0;
+	};
 
-class PausableBackendAdapter :
-	public boost::log::sinks::basic_formatted_sink_backend<char, boost::log::sinks::concurrent_feeding>
-{
-public:
-	PausableBackendAdapter(boost::shared_ptr<boost::log::sinks::text_ostream_backend> backend);
-	~PausableBackendAdapter();
-	void consume(const boost::log::record_view& recordView, const std::string message);
-	void pause();
-	void resume();
-private:
-	boost::shared_ptr<boost::log::sinks::text_ostream_backend> backend;
-	std::vector<std::tuple<boost::log::record_view, std::string>> buffer;
-	std::mutex mutex;
-	bool isPaused = false;
-};
+	class SimpleConsoleFormatter : public Formatter {
+	public:
+		std::string format(const Entry& entry) override;
+	};
 
-boost::shared_ptr<PausableBackendAdapter> addPausableStderrSink(LogLevel minLogLevel);
+	class SimpleFileFormatter : public Formatter {
+	public:
+		std::string format(const Entry& entry) override;
+	private:
+		SimpleConsoleFormatter consoleFormatter;
+	};
 
-void addFileSink(const boost::filesystem::path& logFilePath, LogLevel minLogLevel);
+	class Sink {
+	public:
+		virtual ~Sink() = default;
+		virtual void receive(const Entry& entry) = 0;
+	};
 
-template<typename TValue>
-void logTimedEvent(const std::string& eventName, const Timed<TValue> timedValue) {
-	LOG_DEBUG
-		<< "##" << eventName << "[" << formatDuration(timedValue.getStart()) << "-" << formatDuration(timedValue.getEnd()) << "]: "
-		<< timedValue.getValue();
-}
-
-template<typename TValue>
-void logTimedEvent(const std::string& eventName, const TimeRange& timeRange, const TValue& value) {
-	logTimedEvent(eventName, Timed<TValue>(timeRange, value));
-}
-
-template<typename TValue>
-void logTimedEvent(const std::string& eventName, centiseconds start, centiseconds end, const TValue& value) {
-	logTimedEvent(eventName, Timed<TValue>(start, end, value));
+	class LevelFilter : public Sink {
+	public:
+		LevelFilter(std::shared_ptr<Sink> innerSink, Level minLevel);
+		void receive(const Entry& entry) override;
+	private:
+		std::shared_ptr<Sink> innerSink;
+		Level minLevel;
+	};
+
+	class StreamSink : public Sink {
+	public:
+		StreamSink(std::shared_ptr<std::ostream> stream, std::shared_ptr<Formatter> formatter);
+		void receive(const Entry& entry) override;
+	private:
+		std::shared_ptr<std::ostream> stream;
+		std::shared_ptr<Formatter> formatter;
+	};
+
+	class StdErrSink : public StreamSink {
+	public:
+		explicit StdErrSink(std::shared_ptr<Formatter> formatter);
+	};
+
+	class PausableSink : public Sink {
+	public:
+		explicit PausableSink(std::shared_ptr<Sink> innerSink);
+		void receive(const Entry& entry) override;
+		void pause();
+		void resume();
+	private:
+		std::shared_ptr<Sink> innerSink;
+		std::vector<Entry> buffer;
+		std::mutex mutex;
+		bool isPaused = false;
+	};
+
+	void addSink(std::shared_ptr<Sink> sink);
+
+	void log(Level level, const std::string& message);
+
+	template <typename... Args>
+	void logFormat(Level level, fmt::CStringRef format, const Args&... args) {
+		log(level, fmt::format(format, args...));
+	}
+
+#define LOG_WITH_LEVEL(levelName, levelEnum) \
+	inline void levelName(const std::string& message) { \
+		log(Level::levelEnum, message); \
+	} \
+	template <typename... Args> \
+	void levelName ## Format(fmt::CStringRef format, const Args&... args) { \
+		logFormat(Level::levelEnum, format, args...); \
+	}
+
+	LOG_WITH_LEVEL(trace, Trace)
+	LOG_WITH_LEVEL(debug, Debug)
+	LOG_WITH_LEVEL(info, Info)
+	LOG_WITH_LEVEL(warn, Warn)
+	LOG_WITH_LEVEL(error, Error)
+	LOG_WITH_LEVEL(fatal, Fatal)
+
+	template<typename TValue>
+	void logTimedEvent(const std::string& eventName, const Timed<TValue> timedValue) {
+		debugFormat("##{0} [{1}-{2}]: {3}",
+			eventName, formatDuration(timedValue.getStart()), formatDuration(timedValue.getEnd()), timedValue.getValue());
+	}
+
+	template<typename TValue>
+	void logTimedEvent(const std::string& eventName, const TimeRange& timeRange, const TValue& value) {
+		logTimedEvent(eventName, Timed<TValue>(timeRange, value));
+	}
+
+	template<typename TValue>
+	void logTimedEvent(const std::string& eventName, centiseconds start, centiseconds end, const TValue& value) {
+		logTimedEvent(eventName, Timed<TValue>(start, end, value));
+	}
 }

src/main.cpp

@@ -18,6 +18,8 @@ using std::string;
 using std::vector;
 using std::unique_ptr;
 using std::make_unique;
+using std::shared_ptr;
+using std::make_shared;
 using std::map;
 using std::chrono::duration;
 using std::chrono::duration_cast;
@@ -47,7 +49,7 @@ unique_ptr<AudioStream> createAudioStream(path filePath) {
 // Tell TCLAP how to handle our types
 namespace TCLAP {
 	template<>
-	struct ArgTraits<LogLevel> {
+	struct ArgTraits<logging::Level> {
 		typedef ValueLike ValueCategory;
 	};
 	template<>
@@ -56,8 +58,25 @@ namespace TCLAP {
 	};
 }
 
+shared_ptr<logging::PausableSink> addPausableStdErrSink(logging::Level minLevel) {
+	auto stdErrSink = make_shared<logging::StdErrSink>(make_shared<logging::SimpleConsoleFormatter>());
+	auto pausableSink = make_shared<logging::PausableSink>(stdErrSink);
+	auto levelFilter = make_shared<logging::LevelFilter>(pausableSink, minLevel);
+	logging::addSink(levelFilter);
+	return pausableSink;
+}
+
+void addFileSink(path path, logging::Level minLevel) {
+	auto file = make_shared<boost::filesystem::ofstream>();
+	file->exceptions(std::ifstream::failbit | std::ifstream::badbit);
+	file->open(path);
+	auto FileSink = make_shared<logging::StreamSink>(file, make_shared<logging::SimpleFileFormatter>());
+	auto levelFilter = make_shared<logging::LevelFilter>(FileSink, minLevel);
+	logging::addSink(levelFilter);
+}
+
 int main(int argc, char *argv[]) {
-	auto pausableStderrSink = addPausableStderrSink(LogLevel::Warning);
+	auto pausableStderrSink = addPausableStdErrSink(logging::Level::Warn);
 	pausableStderrSink->pause();
 
 	// Define command-line parameters
@@ -65,9 +84,9 @@ int main(int argc, char *argv[]) {
 	tclap::CmdLine cmd(appName, argumentValueSeparator, appVersion);
 	cmd.setExceptionHandling(false);
 	cmd.setOutput(new NiceCmdLineOutput());
-	auto logLevels = vector<LogLevel>(getEnumValues<LogLevel>());
-	tclap::ValuesConstraint<LogLevel> logLevelConstraint(logLevels);
-	tclap::ValueArg<LogLevel> logLevel("", "logLevel", "The minimum log level to log", false, LogLevel::Debug, &logLevelConstraint, cmd);
+	auto logLevels = vector<logging::Level>(getEnumValues<logging::Level>());
+	tclap::ValuesConstraint<logging::Level> logLevelConstraint(logLevels);
+	tclap::ValueArg<logging::Level> logLevel("", "logLevel", "The minimum log level to log", false, logging::Level::Debug, &logLevelConstraint, cmd);
 	tclap::ValueArg<string> logFileName("", "logFile", "The log file path.", false, string(), "string", cmd);
 	tclap::ValueArg<string> dialog("d", "dialog", "The text of the dialog.", false, string(), "string", cmd);
 	auto exportFormats = vector<ExportFormat>(getEnumValues<ExportFormat>());

src/mouthAnimation.cpp

@@ -72,7 +72,7 @@ Timeline<Shape> animate(const Timeline<Phone> &phones) {
 	for (auto& timedPhone : phones) {
 		Timed<Shape> timedShape(static_cast<TimeRange>(timedPhone), getShape(timedPhone.getValue()));
 		shapes.set(timedShape);
-		logTimedEvent("shape", timedShape);
+		logging::logTimedEvent("shape", timedShape);
 	}
 
 	return shapes;

src/phoneExtraction.cpp

@@ -98,18 +98,18 @@ void processAudioStream(AudioStream& audioStream16kHz, function<void(const vecto
 	} while (buffer.size());
 }
 
-LogLevel ConvertSphinxErrorLevel(err_lvl_t errorLevel) {
+logging::Level ConvertSphinxErrorLevel(err_lvl_t errorLevel) {
 	switch (errorLevel) {
 	case ERR_DEBUG:
 	case ERR_INFO:
 	case ERR_INFOCONT:
-		return LogLevel::Trace;
+		return logging::Level::Trace;
 	case ERR_WARN:
-		return LogLevel::Warning;
+		return logging::Level::Warn;
 	case ERR_ERROR:
-		return LogLevel::Error;
+		return logging::Level::Error;
 	case ERR_FATAL:
-		return LogLevel::Fatal;
+		return logging::Level::Fatal;
 	default:
 		throw invalid_argument("Unknown log level.");
 	}
@@ -137,8 +137,8 @@ void sphinxLogCallback(void* user_data, err_lvl_t errorLevel, const char* format
 	string message(chars.data());
 	boost::algorithm::trim(message);
 
-	LogLevel logLevel = ConvertSphinxErrorLevel(errorLevel);
-	LOG(logLevel) << message;
+	logging::Level logLevel = ConvertSphinxErrorLevel(errorLevel);
+	logging::log(logLevel, message);
 }
 
 vector<string> recognizeWords(unique_ptr<AudioStream> audioStream, ps_decoder_t& recognizer, ProgressSink& progressSink) {
@@ -169,7 +169,7 @@ vector<string> recognizeWords(unique_ptr<AudioStream> audioStream, ps_decoder_t&
 
 		int firstFrame, lastFrame;
 		ps_seg_frames(it, &firstFrame, &lastFrame);
-		logTimedEvent("word", centiseconds(firstFrame), centiseconds(lastFrame + 1), word);
+		logging::logTimedEvent("word", centiseconds(firstFrame), centiseconds(lastFrame + 1), word);
 	}
 
 	return result;
@@ -278,7 +278,7 @@ Timeline<Phone> getPhoneAlignment(const vector<s3wid_t>& wordIds, unique_ptr<Aud
 		Timed<Phone> timedPhone(start, start + duration, parseEnum<Phone>(phoneName));
 		result.set(timedPhone);
 
-		logTimedEvent("phone", timedPhone);
+		logging::logTimedEvent("phone", timedPhone);
 	}
 	return result;
 }

src/tools.cpp

@@ -1,6 +1,7 @@
 #include "tools.h"
 #include <format.h>
 #include <chrono>
+#include <vector>
 
 using std::string;
 using std::chrono::duration;
@@ -8,3 +9,14 @@ using std::chrono::duration;
 string formatDuration(duration<double> seconds) {
 	return fmt::format("{0:.2f}", seconds.count());
 }
+
+string formatTime(time_t time, const string& format) {
+	tm* timeInfo = localtime(&time);
+	std::vector<char> buffer(20);
+	bool success = false;
+	while (!success) {
+		success = strftime(buffer.data(), buffer.size(), format.c_str(), timeInfo) != 0;
+		if (!success) buffer.resize(buffer.size() * 2);
+	}
+	return string(buffer.data());
+}

src/tools.h

@@ -10,3 +10,5 @@ template<typename T>
 using lambda_unique_ptr = std::unique_ptr<T, std::function<void(T*)>>;
 
 std::string formatDuration(std::chrono::duration<double> seconds);
+
+std::string formatTime(time_t time, const std::string& format);