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

1 files changed, 109 insertions, 70 deletions

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