Implement thread-safety in the logging system

This chooses a method that minimizes the need to alter the way log messages are written.
Only a few places that did unusual things with the logger needed to be updated.

src/deprecation.cpp

@@ -77,7 +77,7 @@ std::string deprecated_message(
 
 	if(log_ptr && !log_ptr->dont_log(log_deprecate)) {
 		const lg::logger& out_log = *log_ptr;
-		out_log(log_deprecate) << message << '\n';
+		FORCE_LOG_TO(out_log, log_deprecate) << message << '\n';
 
 		if(preferences::get("show_deprecation", false)) {
 			lg::wml_error() << message << '\n';

src/font/pango/stream_ops.hpp

@@ -17,12 +17,8 @@
 #include <pango/pango.h>
 #include <ostream>
 
-namespace font {
-
 inline std::ostream& operator<<(std::ostream& s, const PangoRectangle &rect)
 {
 	s << rect.x << ',' << rect.y << " x " << rect.width << ',' << rect.height;
 	return s;
 }
-
-} // end namespace font

src/formatter.hpp

@@ -67,6 +67,31 @@ class formatter
 	{
 		return stream_.str();
 	}
+
+	// Support manipulators
+    formatter& operator<<(std::ostream&(*fn)(std::ostream&)) &
+	{
+        fn(stream_);
+		return *this;
+    }
+
+    formatter&& operator<<(std::ostream&(*fn)(std::ostream&)) &&
+	{
+        fn(stream_);
+		return std::move(*this);
+    }
+
+    formatter& operator<<(std::ios_base&(*fn)(std::ios_base&)) &
+	{
+        fn(stream_);
+		return *this;
+    }
+
+    formatter&& operator<<(std::ios_base&(*fn)(std::ios_base&)) &&
+	{
+        fn(stream_);
+		return std::move(*this);
+    }
 
 private:
 	std::ostringstream stream_;

src/game_config_manager.cpp

@@ -129,12 +129,13 @@ bool map_includes(const preproc_map& general, const preproc_map& special)
 }
 } // end anonymous namespace
 
+#define LOG_GC_DEFINES FORCE_LOG_TO(out, log_config)
 void game_config_manager::load_game_config_with_loadscreen(FORCE_RELOAD_CONFIG force_reload,
 	game_classification const*,
 	boost::optional<std::set<std::string>> active_addons)
 {
 	if (!lg::info().dont_log(log_config)) {
-		auto& out = lg::info()(log_config);
+		auto out = formatter();
 		out << "load_game_config: defines:";
 		for(const auto& pair : cache_.get_preproc_map()) {
 			out << pair.first << ",";
@@ -149,6 +150,7 @@ void game_config_manager::load_game_config_with_loadscreen(FORCE_RELOAD_CONFIG f
 			out << "\n Everything:";
 		}
 		out << "\n";
+		FORCE_LOG_TO(lg::info(), log_config) << out.str();
 	} 
 
 

src/game_events/pump.cpp

@@ -402,7 +402,7 @@ void wml_event_pump::show_wml_messages()
 void wml_event_pump::put_wml_message(
 		lg::logger& logger, const std::string& prefix, const std::string& message, bool in_chat)
 {
-	logger(log_wml) << message << std::endl;
+	FORCE_LOG_TO(logger, log_wml) << message << std::endl;
 	if(in_chat) {
 		impl_->wml_messages_stream << prefix << message << std::endl;
 	}

src/gui/core/log.hpp

@@ -43,11 +43,8 @@ extern lg::log_domain log_gui_general;
 #define ERR_GUI_G LOG_STREAM_INDENT(err, gui2::log_gui_general)
 
 extern lg::log_domain log_gui_iterator;
-#define TST_GUI_I                                                              \
-	if(lg::debug().dont_log(gui2::log_gui_iterator))                             \
-		;                                                                      \
-	else                                                                       \
-	lg::debug()(gui2::log_gui_iterator, false, false)
+
+#define TST_GUI_I LOG_STREAM_NAMELESS(debug, gui2::log_gui_iterator)
 #define DBG_GUI_I LOG_STREAM_INDENT(debug, gui2::log_gui_iterator)
 #define LOG_GUI_I LOG_STREAM_INDENT(info, gui2::log_gui_iterator)
 #define WRN_GUI_I LOG_STREAM_INDENT(warn, gui2::log_gui_iterator)

src/log.cpp

@@ -26,6 +26,7 @@
 #include <map>
 #include <sstream>
 #include <ctime>
+#include <mutex>
 
 #include "global.hpp"
 
@@ -44,6 +45,7 @@ static std::ostream null_ostream(new null_streambuf);
 static int indent = 0;
 static bool timestamp = true;
 static bool precise_timestamp = false;
+static std::mutex log_mutex;
 
 static boost::posix_time::time_facet facet("%Y%m%d %H:%M:%S%F ");
 static std::ostream *output_stream = nullptr;
@@ -207,7 +209,7 @@ static void print_precise_timestamp(std::ostream & out) noexcept
 	} catch(...) {}
 }
 
-std::ostream &logger::operator()(const log_domain& domain, bool show_names, bool do_indent) const
+log_in_progress logger::operator()(const log_domain& domain, bool show_names, bool do_indent) const
 {
 	if (severity_ > domain.domain_->second) {
 		return null_ostream;
@@ -218,33 +220,58 @@ std::ostream &logger::operator()(const log_domain& domain, bool show_names, bool
 			std::cerr << ss.str() << std::endl;
 			strict_threw_ = true;
 		}
-		std::ostream& stream = output();
+		log_in_progress stream = output();
 		if(do_indent) {
-			for(int i = 0; i != indent; ++i)
-				stream << "  ";
-			}
+			stream.set_indent(indent);
+		}
 		if (timestamp) {
-			if(precise_timestamp) {
-				print_precise_timestamp(stream);
-			} else {
-				stream << get_timestamp(std::time(nullptr));
-			}
+			stream.enable_timestamp();
 		}
 		if (show_names) {
-			stream << name_ << ' ' << domain.domain_->first << ": ";
+			stream.set_prefix(formatter() << name_ << ' ' << domain.domain_->first << ": ");
 		}
 		return stream;
 	}
 }
 
-void scope_logger::do_log_entry(const log_domain& domain, const std::string& str) noexcept
+log_in_progress::log_in_progress(std::ostream& stream)
+	: stream_(stream)
+{}
+
+void log_in_progress::operator|(formatter&& message)
+{
+	std::lock_guard<std::mutex> lock(log_mutex);
+	for(int i = 0; i < indent; ++i)
+		stream_ << "  ";
+	if(timestamp_) {
+		if(precise_timestamp) {
+			print_precise_timestamp(stream_);
+		} else {
+			stream_ << get_timestamp(std::time(nullptr));
+		}
+	}
+	stream_ << prefix_ << message.str();
+}
+
+void log_in_progress::set_indent(int level) {
+	indent_ = level;
+}
+
+void log_in_progress::enable_timestamp() {
+	timestamp_ = true;
+}
+
+void log_in_progress::set_prefix(const std::string& prefix) {
+	prefix_ = prefix;
+}
+
+void scope_logger::do_log_entry(const std::string& str) noexcept
 {
-	output_ = &debug()(domain, false, true);
 	str_ = str;
 	try {
 		ticks_ = boost::posix_time::microsec_clock::local_time();
 	} catch(...) {}
-	(*output_) << "{ BEGIN: " << str_ << "\n";
+	debug()(domain_, false, true) | formatter() << "{ BEGIN: " << str_ << "\n";
 	++indent;
 }
 
@@ -255,15 +282,10 @@ void scope_logger::do_log_exit() noexcept
 		ticks = (boost::posix_time::microsec_clock::local_time() - ticks_).total_milliseconds();
 	} catch(...) {}
 	--indent;
-	do_indent();
-	if (timestamp) (*output_) << get_timestamp(std::time(nullptr));
-	(*output_) << "} END: " << str_ << " (took " << ticks << "ms)\n";
-}
-
-void scope_logger::do_indent() const
-{
-	for(int i = 0; i != indent; ++i)
-		(*output_) << "  ";
+	auto output = debug()(domain_, false, true);
+	output.set_indent(indent);
+	if(timestamp) output.enable_timestamp();
+	output | formatter() << "} END: " << str_ << " (took " << ticks << "ms)\n";
 }
 
 std::stringstream& wml_error()

src/log.hpp

@@ -58,6 +58,7 @@
 #include <utility>
 
 #include <boost/date_time/posix_time/posix_time_types.hpp>
+#include "formatter.hpp"
 
 using boost::posix_time::ptime;
 
@@ -112,12 +113,32 @@ void set_strict_severity(int severity);
 void set_strict_severity(const logger &lg);
 bool broke_strict();
 
+// A little "magic" to surround the logging operation in a mutex.
+// This works by capturing the output first to a stringstream formatter, then
+// locking a mutex and dumping it to the stream all in one go.
+// By doing this we can avoid rare deadlocks if a function whose output is streamed
+// calls logging of its own.
+// We overload operator| only because it has lower precedence than operator<<
+// Any other lower-precedence operator would have worked just as well.
+class log_in_progress {
+	std::ostream& stream_;
+	int indent_ = 0;
+	bool timestamp_ = false;
+	std::string prefix_;
+public:
+	log_in_progress(std::ostream& stream);
+	void operator|(formatter&& message);
+	void set_indent(int level);
+	void enable_timestamp();
+	void set_prefix(const std::string& prefix);
+};
+
 class logger {
 	char const *name_;
 	int severity_;
 public:
 	logger(char const *name, int severity): name_(name), severity_(severity) {}
-	std::ostream &operator()(const log_domain& domain,
+	log_in_progress operator()(const log_domain& domain,
 		bool show_names = true, bool do_indent = false) const;
 
 	bool dont_log(const log_domain& domain) const
@@ -147,26 +168,25 @@ log_domain& general();
 class scope_logger
 {
 	ptime ticks_;
-	std::ostream *output_;
+	const log_domain& domain_;
 	std::string str_;
 public:
 	scope_logger(const log_domain& domain, const char* str) :
-		output_(nullptr)
+		domain_(domain)
 	{
-		if (!debug().dont_log(domain)) do_log_entry(domain, str);
+		if (!debug().dont_log(domain)) do_log_entry(str);
 	}
 	scope_logger(const log_domain& domain, const std::string& str) :
-		output_(nullptr)
+		domain_(domain)
 	{
-		if (!debug().dont_log(domain)) do_log_entry(domain, str);
+		if (!debug().dont_log(domain)) do_log_entry(str);
 	}
 	~scope_logger()
 	{
-		if (output_) do_log_exit();
+		if (!str_.empty()) do_log_exit();
 	}
-	void do_indent() const;
 private:
-	void do_log_entry(const log_domain& domain, const std::string& str) noexcept;
+	void do_log_entry(const std::string& str) noexcept;
 	void do_log_exit() noexcept;
 };
 
@@ -186,7 +206,14 @@ std::stringstream& wml_error();
 #define log_scope(description) lg::scope_logger scope_logging_object__(lg::general(), description);
 #define log_scope2(domain,description) lg::scope_logger scope_logging_object__(domain, description);
 
-#define LOG_STREAM(level, domain) if (lg::level().dont_log(domain)) ; else lg::level()(domain)
+#define LOG_STREAM(level, domain) if (lg::level().dont_log(domain)) ; else lg::level()(domain) | formatter()
+
+// Don't prefix the logdomain to messages on this stream
+#define LOG_STREAM_NAMELESS(level, domain) if (lg::level().dont_log(domain)) ; else lg::level()(domain, false) | formatter()
 
 // When using log_scope/log_scope2 it is nice to have all output indented.
-#define LOG_STREAM_INDENT(level,domain) if (lg::level().dont_log(domain)) ; else lg::level()(domain, true, true)
+#define LOG_STREAM_INDENT(level,domain) if (lg::level().dont_log(domain)) ; else lg::level()(domain, true, true) | formatter()
+
+// If you have an explicit logger object and want to ignore the logging level, use this.
+// Meant for cases where you explicitly call dont_log to avoid an expensive operation if the logging is disabled.
+#define FORCE_LOG_TO(logger, domain) logger(domain) | formatter()