multi-line logging improvements (#597)

* added ZEN_SCOPED_WARN and implemented multi-line logging
* changed so file log also uses `fullformatter` for consistency and to get the multi-line support across the board

4 files changed, 127 insertions, 78 deletions

diff --git a/src/zencore/include/zencore/logging.h b/src/zencore/include/zencore/logging.h
index 8b76d754c..6d44e31df 100644
--- a/src/zencore/include/zencore/logging.h
+++ b/src/zencore/include/zencore/logging.h
@@ -239,6 +239,14 @@ std::string_view EmitActivitiesForLogging(StringBuilderBase& OutString);
 
 #define ZEN_LOG_SCOPE(...) ScopedLazyActivity $Activity##__LINE__([&](StringBuilderBase& Out) { Out << fmt::format(__VA_ARGS__); })
 
+#define ZEN_SCOPED_WARN(fmtstr, ...)                                                   \
+	do                                                                                 \
+	{                                                                                  \
+		ExtendableStringBuilder<256> ScopeString;                                      \
+		const std::string_view		 Scopes = EmitActivitiesForLogging(ScopeString);   \
+		ZEN_LOG(Log(), zen::logging::level::Warn, fmtstr "{}", ##__VA_ARGS__, Scopes); \
+	} while (false)
+
 #define ZEN_SCOPED_ERROR(fmtstr, ...)                                                               \
 	do                                                                                              \
 	{                                                                                               \
diff --git a/src/zenserver/zenserver.cpp b/src/zenserver/zenserver.cpp
index 2aeb6a4d5..418e3c325 100644
--- a/src/zenserver/zenserver.cpp
+++ b/src/zenserver/zenserver.cpp
@@ -565,12 +565,13 @@ ZenServer::Run()
 
 	if (!m_TestMode)
 	{
-		ZEN_INFO("__________                _________ __                        ");
-		ZEN_INFO("\\____    /____   ____    /   _____//  |_  ___________   ____  ");
-		ZEN_INFO("  /     // __ \\ /    \\   \\_____  \\\\   __\\/  _ \\_  __ \\_/ __ \\ ");
-		ZEN_INFO(" /     /\\  ___/|   |  \\  /        \\|  | (  <_> )  | \\/\\  ___/ ");
-		ZEN_INFO("/_______ \\___  >___|  / /_______  /|__|  \\____/|__|    \\___  >");
-		ZEN_INFO("        \\/   \\/     \\/          \\/                         \\/ ");
+		ZEN_INFO(
+			"__________                _________ __                        \n"
+			"\\____    /____   ____    /   _____//  |_  ___________   ____  \n"
+			"  /     // __ \\ /    \\   \\_____  \\\\   __\\/  _ \\_  __ \\_/ __ \\ \n"
+			" /     /\\  ___/|   |  \\  /        \\|  | (  <_> )  | \\/\\  ___/ \n"
+			"/_______ \\___  >___|  / /_______  /|__|  \\____/|__|    \\___  >\n"
+			"        \\/   \\/     \\/          \\/                         \\/ \n");
 	}
 
 	ZEN_INFO(ZEN_APP_NAME " now running (pid: {})", GetCurrentProcessId());
diff --git a/src/zenutil/include/zenutil/logging/fullformatter.h b/src/zenutil/include/zenutil/logging/fullformatter.h
index 498ecd143..146fea7a0 100644
--- a/src/zenutil/include/zenutil/logging/fullformatter.h
+++ b/src/zenutil/include/zenutil/logging/fullformatter.h
@@ -16,136 +16,175 @@ namespace zen::logging {
 class full_formatter final : public spdlog::formatter
 {
 public:
-	full_formatter(std::string_view LogId, std::chrono::time_point<std::chrono::system_clock> Epoch) : m_Epoch(Epoch), m_LogId(LogId) {}
+	full_formatter(std::string_view LogId, std::chrono::time_point<std::chrono::system_clock> Epoch)
+	: m_Epoch(Epoch)
+	, m_LogId(LogId)
+	, m_LinePrefix(128, ' ')
+	, m_UseFullDate(false)
+	{
+	}
 
-	virtual std::unique_ptr<formatter> clone() const override { return std::make_unique<full_formatter>(m_LogId, m_Epoch); }
+	full_formatter(std::string_view LogId) : m_LogId(LogId), m_LinePrefix(128, ' '), m_UseFullDate(true) {}
 
-	static constexpr bool UseDate = false;
+	virtual std::unique_ptr<formatter> clone() const override { return std::make_unique<full_formatter>(m_LogId, m_Epoch); }
 
-	virtual void format(const spdlog::details::log_msg& msg, spdlog::memory_buf_t& dest) override
+	virtual void format(const spdlog::details::log_msg& msg, spdlog::memory_buf_t& OutBuffer) override
 	{
-		using namespace std::literals;
-
-		if constexpr (UseDate)
-		{
-			auto secs = std::chrono::duration_cast<std::chrono::seconds>(msg.time.time_since_epoch());
-			if (secs != m_LastLogSecs)
-			{
-				m_CachedTm	  = spdlog::details::os::localtime(spdlog::log_clock::to_time_t(msg.time));
-				m_LastLogSecs = secs;
-			}
-		}
+		// Note that the sink is responsible for ensuring there is only ever a
+		// single caller in here
 
-		const auto& tm_time = m_CachedTm;
+		using namespace std::literals;
 
-		// cache the date/time part for the next second.
-		auto duration = msg.time - m_Epoch;
-		auto secs	  = std::chrono::duration_cast<std::chrono::seconds>(duration);
+		std::chrono::seconds TimestampSeconds;
 
-		if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0)
+		if (m_UseFullDate)
 		{
-			m_CachedDatetime.clear();
-			m_CachedDatetime.push_back('[');
-
-			if constexpr (UseDate)
+			TimestampSeconds = std::chrono::duration_cast<std::chrono::seconds>(msg.time.time_since_epoch());
+			if (TimestampSeconds != m_LastLogSecs)
 			{
-				spdlog::details::fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime);
-				m_CachedDatetime.push_back('-');
+				m_LastLogSecs = TimestampSeconds;
 
-				spdlog::details::fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime);
+				m_CachedLocalTm = spdlog::details::os::localtime(spdlog::log_clock::to_time_t(msg.time));
+				m_CachedDatetime.clear();
+				m_CachedDatetime.push_back('[');
+				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_year % 100, m_CachedDatetime);
 				m_CachedDatetime.push_back('-');
-
-				spdlog::details::fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_mon + 1, m_CachedDatetime);
+				m_CachedDatetime.push_back('-');
+				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_mday, m_CachedDatetime);
 				m_CachedDatetime.push_back(' ');
-
-				spdlog::details::fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_hour, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
-
-				spdlog::details::fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_min, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
-
-				spdlog::details::fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_sec, m_CachedDatetime);
+				m_CachedDatetime.push_back('.');
 			}
-			else
+		}
+		else
+		{
+			auto ElapsedTime = msg.time - m_Epoch;
+			TimestampSeconds = std::chrono::duration_cast<std::chrono::seconds>(ElapsedTime);
+
+			// cache the date/time part for the next second.
+
+			if (m_CacheTimestamp != TimestampSeconds || m_CachedDatetime.size() == 0)
 			{
-				int Count = int(secs.count());
+				m_CacheTimestamp = TimestampSeconds;
 
+				int		  Count	  = int(TimestampSeconds.count());
 				const int LogSecs = Count % 60;
 				Count /= 60;
-
 				const int LogMins = Count % 60;
 				Count /= 60;
-
 				const int LogHours = Count;
 
+				m_CachedDatetime.clear();
+				m_CachedDatetime.push_back('[');
 				spdlog::details::fmt_helper::pad2(LogHours, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
 				spdlog::details::fmt_helper::pad2(LogMins, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
 				spdlog::details::fmt_helper::pad2(LogSecs, m_CachedDatetime);
+				m_CachedDatetime.push_back('.');
 			}
-
-			m_CachedDatetime.push_back('.');
-
-			m_CacheTimestamp = secs;
 		}
 
-		dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end());
+		OutBuffer.append(m_CachedDatetime.begin(), m_CachedDatetime.end());
 
 		auto millis = spdlog::details::fmt_helper::time_fraction<std::chrono::milliseconds>(msg.time);
-		spdlog::details::fmt_helper::pad3(static_cast<uint32_t>(millis.count()), dest);
-		dest.push_back(']');
-		dest.push_back(' ');
+		spdlog::details::fmt_helper::pad3(static_cast<uint32_t>(millis.count()), OutBuffer);
+		OutBuffer.push_back(']');
+		OutBuffer.push_back(' ');
 
 		if (!m_LogId.empty())
 		{
-			dest.push_back('[');
-			spdlog::details::fmt_helper::append_string_view(m_LogId, dest);
-			dest.push_back(']');
-			dest.push_back(' ');
+			OutBuffer.push_back('[');
+			spdlog::details::fmt_helper::append_string_view(m_LogId, OutBuffer);
+			OutBuffer.push_back(']');
+			OutBuffer.push_back(' ');
 		}
 
 		// append logger name if exists
 		if (msg.logger_name.size() > 0)
 		{
-			dest.push_back('[');
-			spdlog::details::fmt_helper::append_string_view(msg.logger_name, dest);
-			dest.push_back(']');
-			dest.push_back(' ');
+			OutBuffer.push_back('[');
+			spdlog::details::fmt_helper::append_string_view(msg.logger_name, OutBuffer);
+			OutBuffer.push_back(']');
+			OutBuffer.push_back(' ');
 		}
 
-		dest.push_back('[');
+		OutBuffer.push_back('[');
 		// wrap the level name with color
-		msg.color_range_start = dest.size();
-		spdlog::details::fmt_helper::append_string_view(spdlog::level::to_string_view(msg.level), dest);
-		msg.color_range_end = dest.size();
-		dest.push_back(']');
-		dest.push_back(' ');
+		msg.color_range_start = OutBuffer.size();
+		spdlog::details::fmt_helper::append_string_view(spdlog::level::to_string_view(msg.level), OutBuffer);
+		msg.color_range_end = OutBuffer.size();
+		OutBuffer.push_back(']');
+		OutBuffer.push_back(' ');
 
 		// add source location if present
 		if (!msg.source.empty())
 		{
-			dest.push_back('[');
+			OutBuffer.push_back('[');
 			const char* filename =
 				spdlog::details::short_filename_formatter<spdlog::details::null_scoped_padder>::basename(msg.source.filename);
-			spdlog::details::fmt_helper::append_string_view(filename, dest);
-			dest.push_back(':');
-			spdlog::details::fmt_helper::append_int(msg.source.line, dest);
-			dest.push_back(']');
-			dest.push_back(' ');
+			spdlog::details::fmt_helper::append_string_view(filename, OutBuffer);
+			OutBuffer.push_back(':');
+			spdlog::details::fmt_helper::append_int(msg.source.line, OutBuffer);
+			OutBuffer.push_back(']');
+			OutBuffer.push_back(' ');
 		}
 
-		spdlog::details::fmt_helper::append_string_view(msg.payload, dest);
-		spdlog::details::fmt_helper::append_string_view("\n"sv, dest);
+		// Handle newlines in single log call by prefixing each additional line to make
+		// subsequent lines align with the first line in the message
+
+		const size_t LinePrefixCount = Min<size_t>(OutBuffer.size(), m_LinePrefix.size());
+
+		auto ItLineBegin  = msg.payload.begin();
+		auto ItMessageEnd = msg.payload.end();
+		bool IsFirstline  = true;
+
+		{
+			auto ItLineEnd = ItLineBegin;
+
+			auto EmitLine = [&] {
+				if (IsFirstline)
+				{
+					IsFirstline = false;
+				}
+				else
+				{
+					spdlog::details::fmt_helper::append_string_view(std::string_view(m_LinePrefix.data(), LinePrefixCount), OutBuffer);
+				}
+				spdlog::details::fmt_helper::append_string_view(spdlog::string_view_t(&*ItLineBegin, ItLineEnd - ItLineBegin), OutBuffer);
+			};
+
+			while (ItLineEnd != ItMessageEnd)
+			{
+				if (*ItLineEnd++ == '\n')
+				{
+					EmitLine();
+					ItLineBegin = ItLineEnd;
+				}
+			}
+
+			if (ItLineBegin != ItMessageEnd)
+			{
+				EmitLine();
+				spdlog::details::fmt_helper::append_string_view("\n"sv, OutBuffer);
+			}
+		}
 	}
 
 private:
 	std::chrono::time_point<std::chrono::system_clock> m_Epoch;
-	std::tm											   m_CachedTm;
+	std::tm											   m_CachedLocalTm;
 	std::chrono::seconds							   m_LastLogSecs;
 	std::chrono::seconds							   m_CacheTimestamp{0};
 	spdlog::memory_buf_t							   m_CachedDatetime;
 	std::string										   m_LogId;
+	std::string										   m_LinePrefix;
+	bool											   m_UseFullDate = true;
 };
 
 }  // namespace zen::logging
diff --git a/src/zenutil/logging.cpp b/src/zenutil/logging.cpp
index d82789e42..fedfdc7e8 100644
--- a/src/zenutil/logging.cpp
+++ b/src/zenutil/logging.cpp
@@ -170,7 +170,8 @@ FinishInitializeLogging(const LoggingOptions& LogOptions)
 	logging::RefreshLogLevels(LogLevel);
 	spdlog::flush_on(spdlog::level::err);
 	spdlog::flush_every(std::chrono::seconds{2});
-	spdlog::set_formatter(std::make_unique<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now()));
+	spdlog::set_formatter(
+		std::make_unique<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now()));	 // default to duration prefix
 
 	if (g_FileSink)
 	{
@@ -180,7 +181,7 @@ FinishInitializeLogging(const LoggingOptions& LogOptions)
 		}
 		else
 		{
-			g_FileSink->set_pattern("[%C-%m-%d %T.%e] [%n] [%l] %v");
+			g_FileSink->set_formatter(std::make_unique<logging::full_formatter>(LogOptions.LogId));	 // this will have a date prefix
 		}
 	}