enable json log file (#164)

* Include source location on ZEN_ERROR and ZEN_CRITICAL
* Use proper logging for sentry init status
* format file logger as json if .json extension is given
* changelog

4 files changed, 179 insertions, 23 deletions

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 6ae854336..6cd94a99a 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,7 +1,8 @@
 ##
+- Feature: Adding a `.json` extension to the `--abslog` option will make zenserver log in json format to file
 - Feature: Create release in Sentry and use `sentry_options_set_release` to associate the executable 
 
-## v0.1.4
+## v0.1.5
 - Bugfix: Don't fail entire request if GetCacheValue from Horde fails for a single value
 
 ## v0.1.4
diff --git a/zencore/include/zencore/logging.h b/zencore/include/zencore/logging.h
index 7c2deeed7..45dbd8c56 100644
--- a/zencore/include/zencore/logging.h
+++ b/zencore/include/zencore/logging.h
@@ -129,18 +129,18 @@ struct LogCategory
 		Log().warn(fmtstr##sv, ##__VA_ARGS__); \
 	} while (false)
 
-#define ZEN_ERROR(fmtstr, ...)                  \
-	do                                          \
-	{                                           \
-		using namespace std::literals;          \
-		Log().error(fmtstr##sv, ##__VA_ARGS__); \
+#define ZEN_ERROR(fmtstr, ...)                                                                                             \
+	do                                                                                                                     \
+	{                                                                                                                      \
+		using namespace std::literals;                                                                                     \
+		Log().log(spdlog::source_loc{__FILE__, __LINE__, SPDLOG_FUNCTION}, spdlog::level::err, fmtstr##sv, ##__VA_ARGS__); \
 	} while (false)
 
-#define ZEN_CRITICAL(fmtstr, ...)                  \
-	do                                             \
-	{                                              \
-		using namespace std::literals;             \
-		Log().critical(fmtstr##sv, ##__VA_ARGS__); \
+#define ZEN_CRITICAL(fmtstr, ...)                                                                                               \
+	do                                                                                                                          \
+	{                                                                                                                           \
+		using namespace std::literals;                                                                                          \
+		Log().log(spdlog::source_loc{__FILE__, __LINE__, SPDLOG_FUNCTION}, spdlog::level::critical, fmtstr##sv, ##__VA_ARGS__); \
 	} while (false)
 
 #define ZEN_CONSOLE(fmtstr, ...)                      \
diff --git a/zenserver/diag/logging.cpp b/zenserver/diag/logging.cpp
index a5620a642..7d4e458cc 100644
--- a/zenserver/diag/logging.cpp
+++ b/zenserver/diag/logging.cpp
@@ -178,6 +178,149 @@ private:
 	std::string										   m_LogId;
 };
 
+class json_formatter final : public spdlog::formatter
+{
+public:
+	json_formatter(std::string_view LogId) : m_LogId(LogId) {}
+
+	virtual std::unique_ptr<formatter> clone() const override { return std::make_unique<json_formatter>(m_LogId); }
+
+	virtual void format(const details::log_msg& msg, memory_buf_t& dest) override
+	{
+		using std::chrono::duration_cast;
+		using std::chrono::milliseconds;
+		using std::chrono::seconds;
+
+		auto secs = std::chrono::duration_cast<seconds>(msg.time.time_since_epoch());
+		if (secs != m_LastLogSecs)
+		{
+			m_CachedTm	  = os::localtime(log_clock::to_time_t(msg.time));
+			m_LastLogSecs = secs;
+		}
+
+		const auto& tm_time = m_CachedTm;
+
+		// cache the date/time part for the next second.
+
+		if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0)
+		{
+			m_CachedDatetime.clear();
+
+			fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime);
+			m_CachedDatetime.push_back('-');
+
+			fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime);
+			m_CachedDatetime.push_back('-');
+
+			fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime);
+			m_CachedDatetime.push_back(' ');
+
+			fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime);
+			m_CachedDatetime.push_back(':');
+
+			fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime);
+			m_CachedDatetime.push_back(':');
+
+			fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime);
+
+			m_CachedDatetime.push_back('.');
+
+			m_CacheTimestamp = secs;
+		}
+		dest.append("{"sv);
+		dest.append("\"time\": \""sv);
+		dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end());
+		auto millis = fmt_helper::time_fraction<milliseconds>(msg.time);
+		fmt_helper::pad3(static_cast<uint32_t>(millis.count()), dest);
+		dest.append("\", "sv);
+
+		dest.append("\"status\": \""sv);
+		dest.append(level::to_string_view(msg.level));
+		dest.append("\", "sv);
+
+		dest.append("\"source\": \""sv);
+		dest.append("zenserver"sv);
+		dest.append("\", "sv);
+
+		if (!m_LogId.empty())
+		{
+			dest.append("\"id\": \""sv);
+			dest.append(m_LogId);
+			dest.append("\", "sv);
+		}
+
+		if (msg.logger_name.size() > 0)
+		{
+			dest.append("\"service\": \""sv);
+			dest.append(msg.logger_name);
+			dest.append("\", "sv);
+		}
+
+		if (msg.thread_id != 0)
+		{
+			dest.append("\"thread\": \""sv);
+			fmt_helper::pad_uint(msg.thread_id, 0, dest);
+			dest.append("\", "sv);
+		}
+
+		if (!msg.source.empty())
+		{
+			dest.append("\"file\": \""sv);
+			WriteEscapedString(dest, details::short_filename_formatter<details::null_scoped_padder>::basename(msg.source.filename));
+			dest.append("\","sv);
+
+			dest.append("\"line\": \""sv);
+			dest.append(fmt::format("{}", msg.source.line));
+			dest.append("\","sv);
+
+			dest.append("\"function\": \""sv);
+			WriteEscapedString(dest, msg.source.funcname);
+			dest.append("\", "sv);
+		}
+
+		dest.append("\"message\": \""sv);
+		WriteEscapedString(dest, msg.payload);
+		dest.append("\""sv);
+
+		dest.append("}\n"sv);
+	}
+
+private:
+	static inline const std::unordered_map<char, std::string_view> SpecialCharacterMap{{'\b', "\\b"sv},
+																					   {'\f', "\\f"sv},
+																					   {'\n', "\\n"sv},
+																					   {'\r', "\\r"sv},
+																					   {'\t', "\\t"sv},
+																					   {'"', "\\\""sv},
+																					   {'\\', "\\\\"sv}};
+
+	static void WriteEscapedString(memory_buf_t& dest, const spdlog::string_view_t& payload)
+	{
+		const char* RangeStart = payload.begin();
+		for (const char* It = RangeStart; It != payload.end(); ++It)
+		{
+			if (auto SpecialIt = SpecialCharacterMap.find(*It); SpecialIt != SpecialCharacterMap.end())
+			{
+				if (RangeStart != It)
+				{
+					dest.append(RangeStart, It);
+				}
+				dest.append(SpecialIt->second);
+				RangeStart = It + 1;
+			}
+		}
+		if (RangeStart != payload.end())
+		{
+			dest.append(RangeStart, payload.end());
+		}
+	};
+
+	std::tm				 m_CachedTm{0, 0, 0, 0, 0, 0, 0, 0, 0};
+	std::chrono::seconds m_LastLogSecs{0};
+	std::chrono::seconds m_CacheTimestamp{0};
+	memory_buf_t		 m_CachedDatetime;
+	std::string			 m_LogId;
+};
 }  // namespace logging
 
 bool
@@ -350,13 +493,21 @@ InitializeLogging(const ZenServerOptions& GlobalOptions)
 	spdlog::flush_every(std::chrono::seconds{2});
 	spdlog::set_formatter(std::make_unique<logging::full_formatter>(GlobalOptions.LogId, std::chrono::system_clock::now()));
 
-	FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v");
-
-	spdlog::info("log starting at {:%FT%T%z}", std::chrono::system_clock::now());
+	if (GlobalOptions.AbsLogFile.extension() == ".json")
+	{
+		FileSink->set_formatter(std::make_unique<logging::json_formatter>(GlobalOptions.LogId));
+	}
+	else
+	{
+		FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v");
+	}
+	DefaultLogger.info("log starting at {:%FT%T%z}", std::chrono::system_clock::now());
 }
 
 void
 ShutdownLogging()
 {
+	auto& DefaultLogger = zen::logging::Default();
+	DefaultLogger.info("log ending at {:%FT%T%z}", std::chrono::system_clock::now());
 	zen::logging::ShutdownLogging();
 }
diff --git a/zenserver/zenserver.cpp b/zenserver/zenserver.cpp
index 759c08476..1c94d80b7 100644
--- a/zenserver/zenserver.cpp
+++ b/zenserver/zenserver.cpp
@@ -948,7 +948,7 @@ ZenEntryPoint::Run()
 {
 #if ZEN_USE_SENTRY
 	std::string SentryDatabasePath = PathToUtf8(m_ServerOptions.DataDir / ".sentry-native");
-
+	int			SentryErrorCode	   = 0;
 	if (m_ServerOptions.NoSentry == false)
 	{
 		sentry_options_t* SentryOptions = sentry_options_new();
@@ -959,14 +959,7 @@ ZenEntryPoint::Run()
 		sentry_options_set_release(SentryOptions, ZEN_CFG_VERSION);
 		// sentry_options_set_debug(SentryOptions, 1);
 
-		if (int ErrorCode = sentry_init(SentryOptions); ErrorCode == 0)
-		{
-			printf("sentry initialized");
-		}
-		else
-		{
-			printf("sentry_init returned failure! (error code: %d)", ErrorCode);
-		}
+		SentryErrorCode = sentry_init(SentryOptions);
 	}
 
 	auto _ = zen::MakeGuard([] { sentry_close(); });
@@ -1002,6 +995,17 @@ ZenEntryPoint::Run()
 
 		InitializeLogging(ServerOptions);
 
+#if ZEN_USE_SENTRY
+		if (SentryErrorCode == 0)
+		{
+			ZEN_INFO("sentry initialized");
+		}
+		else
+		{
+			ZEN_WARN("sentry_init returned failure! (error code: {})", SentryErrorCode);
+		}
+#endif
+
 		MaximizeOpenFileCount();
 
 		ZEN_INFO(ZEN_APP_NAME " - using lock file at '{}'", LockFilePath);