Logging improvements + Colours (new) (#320)

* log colours :)

* commend the freopen stuff (it causes problems)

* formatting

* add explanatory comment

* gaming maybe

* move set pattern

* ok this works now i think

* trailing space :)

* Revert "Merge branch 'main' into log-colours"

This reverts commit d40b6496b7bd3b3f20f51cc2311b0369aeabe735, reversing
changes made to a98bcc22e8961b325806f6a9ca85e64353fd574c.

* Revert "Revert "Merge branch 'main' into log-colours""

This reverts commit da792245b1cd7d0ac9e22d5633770142a43ce10c.

* fix shit maybe

* fix shit but better

* initial, still WIP

* Add GetContextName_Short

* colours for in game console

* working, time to improve code

* rename var + add a colour or two

* whoops

* change rpak filesystem to RP NATIVE

* add RP NATIVE and NORTHSTAR tags

* clang-format off because formatting

* formatting 2

* formatting 3: the formattening

* bruh

* revert unnecessary change

* improve comment

* Set console title to show profile

* pain

* Made code not shit

* Formatting and remove warning box

* Update main.cpp

* Formatting

* More format changes

* Again

* Fix small things from code review

* Remove empty line

* renamed NATIVE_EN -> NATIVE_ENGINE

* Update logging.cpp

* Update sourceconsole.cpp

Co-authored-by: ASpoonPlaysGames <66967891+ASpoonPlaysGames@users.noreply.github.com>

1 files changed, 142 insertions, 208 deletions

diff --git a/NorthstarDLL/logging.cpp b/NorthstarDLL/logging.cpp
index 01775428..233c360e 100644
--- a/NorthstarDLL/logging.cpp
+++ b/NorthstarDLL/logging.cpp
@@ -3,7 +3,6 @@
 #include "convar.h"
 #include "concommand.h"
 #include "nsprefix.h"
-#include "bitbuf.h"
 #include "tier0.h"
 #include "spdlog/sinks/basic_file_sink.h"
 
@@ -12,257 +11,192 @@
 
 AUTOHOOK_INIT()
 
-ConVar* Cvar_spewlog_enable;
+std::vector<std::shared_ptr<ColoredLogger>> loggers {};
 
-enum class SpewType_t
+namespace NS::log
 {
-	SPEW_MESSAGE = 0,
+	std::shared_ptr<ColoredLogger> SCRIPT_UI;
+	std::shared_ptr<ColoredLogger> SCRIPT_CL;
+	std::shared_ptr<ColoredLogger> SCRIPT_SV;
 
-	SPEW_WARNING,
-	SPEW_ASSERT,
-	SPEW_ERROR,
-	SPEW_LOG,
+	std::shared_ptr<ColoredLogger> NATIVE_UI;
+	std::shared_ptr<ColoredLogger> NATIVE_CL;
+	std::shared_ptr<ColoredLogger> NATIVE_SV;
+	std::shared_ptr<ColoredLogger> NATIVE_EN;
 
-	SPEW_TYPE_COUNT
-};
-
-const std::unordered_map<SpewType_t, const char*> PrintSpewTypes = {
-	{SpewType_t::SPEW_MESSAGE, "SPEW_MESSAGE"},
-	{SpewType_t::SPEW_WARNING, "SPEW_WARNING"},
-	{SpewType_t::SPEW_ASSERT, "SPEW_ASSERT"},
-	{SpewType_t::SPEW_ERROR, "SPEW_ERROR"},
-	{SpewType_t::SPEW_LOG, "SPEW_LOG"}};
-
-// clang-format off
-AUTOHOOK(EngineSpewFunc, engine.dll + 0x11CA80,
-void, __fastcall, (void* pEngineServer, SpewType_t type, const char* format, va_list args))
-// clang-format on
-{
-	if (!Cvar_spewlog_enable->GetBool())
-		return;
+	std::shared_ptr<ColoredLogger> fs;
+	std::shared_ptr<ColoredLogger> rpak;
+	std::shared_ptr<ColoredLogger> echo;
 
-	const char* typeStr = PrintSpewTypes.at(type);
-	char formatted[2048] = {0};
-	bool bShouldFormat = true;
+	std::shared_ptr<ColoredLogger> NORTHSTAR;
+}; // namespace NS::log
 
-	// because titanfall 2 is quite possibly the worst thing to yet exist, it sometimes gives invalid specifiers which will crash
-	// ttf2sdk had a way to prevent them from crashing but it doesnt work in debug builds
-	// so we use this instead
-	for (int i = 0; format[i]; i++)
+// This needs to be called after hooks are loaded so we can access the command line args
+void CreateLogFiles()
+{
+	if (strstr(GetCommandLineA(), "-disablelogs"))
 	{
-		if (format[i] == '%')
-		{
-			switch (format[i + 1])
-			{
-			// this is fucking awful lol
-			case 'd':
-			case 'i':
-			case 'u':
-			case 'x':
-			case 'X':
-			case 'f':
-			case 'F':
-			case 'g':
-			case 'G':
-			case 'a':
-			case 'A':
-			case 'c':
-			case 's':
-			case 'p':
-			case 'n':
-			case '%':
-			case '-':
-			case '+':
-			case ' ':
-			case '#':
-			case '*':
-			case '0':
-			case '1':
-			case '2':
-			case '3':
-			case '4':
-			case '5':
-			case '6':
-			case '7':
-			case '8':
-			case '9':
-				break;
-
-			default:
-			{
-				bShouldFormat = false;
-				break;
-			}
-			}
-		}
+		spdlog::default_logger()->set_level(spdlog::level::off);
 	}
-
-	if (bShouldFormat)
-		vsnprintf(formatted, sizeof(formatted), format, args);
 	else
-		spdlog::warn("Failed to format {} \"{}\"", typeStr, format);
-
-	auto endpos = strlen(formatted);
-	if (formatted[endpos - 1] == '\n')
-		formatted[endpos - 1] = '\0'; // cut off repeated newline
+	{
+		try
+		{
+			// todo: might be good to delete logs that are too old
+			time_t time = std::time(nullptr);
+			tm currentTime = *std::localtime(&time);
+			std::stringstream stream;
 
-	spdlog::info("[SERVER {}] {}", typeStr, formatted);
+			stream << std::put_time(&currentTime, (GetNorthstarPrefix() + "/logs/nslog%Y-%m-%d %H-%M-%S.txt").c_str());
+			auto sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(stream.str(), false);
+			sink->set_pattern("[%H:%M:%S] [%n] [%l] %v");
+			spdlog::default_logger()->sinks().push_back(sink);
+			spdlog::flush_on(spdlog::level::info);
+		}
+		catch (...)
+		{
+			spdlog::error("Failed creating log file!");
+			MessageBoxA(
+				0, "Failed creating log file! Make sure the profile directory is writable.", "Northstar Warning", MB_ICONWARNING | MB_OK);
+		}
+	}
 }
 
-// used for printing the output of status
-// clang-format off
-AUTOHOOK(Status_ConMsg, engine.dll + 0x15ABD0,
-void,, (const char* text, ...))
-// clang-format on
+void ExternalConsoleSink::sink_it_(const spdlog::details::log_msg& msg)
 {
-	char formatted[2048];
-	va_list list;
-
-	va_start(list, text);
-	vsprintf_s(formatted, text, list);
-	va_end(list);
-
-	auto endpos = strlen(formatted);
-	if (formatted[endpos - 1] == '\n')
-		formatted[endpos - 1] = '\0'; // cut off repeated newline
-
-	spdlog::info(formatted);
+	throw std::runtime_error("sink_it_ called on SourceConsoleSink with pure log_msg. This is an error!");
 }
 
-// clang-format off
-AUTOHOOK(CClientState_ProcessPrint, engine.dll + 0x1A1530, 
-bool,, (void* thisptr, uintptr_t msg))
-// clang-format on
+void ExternalConsoleSink::custom_sink_it_(const custom_log_msg& msg)
 {
-	char* text = *(char**)(msg + 0x20);
+	spdlog::memory_buf_t formatted;
+	spdlog::sinks::base_sink<std::mutex>::formatter_->format(msg, formatted);
 
-	auto endpos = strlen(text);
-	if (text[endpos - 1] == '\n')
-		text[endpos - 1] = '\0'; // cut off repeated newline
+	std::string out = "";
+	// if ansi colour is turned off, just use WriteConsoleA and return
+	if (!g_bSpdLog_UseAnsiColor)
+	{
+		out += fmt::to_string(formatted);
+	}
 
-	spdlog::info(text);
-	return true;
-}
+	// print to the console with colours
+	else
+	{
+		// get message string
+		std::string str = fmt::to_string(formatted);
 
-ConVar* Cvar_cl_showtextmsg;
+		std::string levelColor = m_LogColours[msg.level];
+		std::string name {msg.logger_name.begin(), msg.logger_name.end()};
 
-class ICenterPrint
-{
-  public:
-	virtual void ctor() = 0;
-	virtual void Clear(void) = 0;
-	virtual void ColorPrint(int r, int g, int b, int a, wchar_t* text) = 0;
-	virtual void ColorPrint(int r, int g, int b, int a, char* text) = 0;
-	virtual void Print(wchar_t* text) = 0;
-	virtual void Print(char* text) = 0;
-	virtual void SetTextColor(int r, int g, int b, int a) = 0;
-};
+		std::string name_str = "[NAME]";
+		int name_pos = str.find(name_str);
+		str.replace(name_pos, name_str.length(), msg.origin->ANSIColor + "[" + name + "]" + default_color);
 
-ICenterPrint* pInternalCenterPrint = NULL;
+		std::string level_str = "[LVL]";
+		int level_pos = str.find(level_str);
+		str.replace(level_pos, level_str.length(), levelColor + "[" + std::string(level_names[msg.level]) + "]" + default_color);
 
-enum class TextMsgPrintType_t
-{
-	HUD_PRINTNOTIFY = 1,
-	HUD_PRINTCONSOLE,
-	HUD_PRINTTALK,
-	HUD_PRINTCENTER
-};
+		out += str;
+	}
+	// print the string to the console - this is definitely bad i think
+	HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);
+	auto ignored = WriteConsoleA(handle, out.c_str(), std::strlen(out.c_str()), nullptr, nullptr);
+	(void)ignored;
+}
 
-// clang-format off
-AUTOHOOK(TextMsg, client.dll + 0x198710,
-void,, (BFRead* msg))
-// clang-format on
+void ExternalConsoleSink::flush_()
 {
-	TextMsgPrintType_t msg_dest = (TextMsgPrintType_t)msg->ReadByte();
-
-	char text[256];
-	msg->ReadString(text, sizeof(text));
-
-	if (!Cvar_cl_showtextmsg->GetBool())
-		return;
-
-	switch (msg_dest)
-	{
-	case TextMsgPrintType_t::HUD_PRINTCENTER:
-		pInternalCenterPrint->Print(text);
-		break;
-
-	default:
-		spdlog::warn("Unimplemented TextMsg type {}! printing to console", msg_dest);
-		[[fallthrough]];
-
-	case TextMsgPrintType_t::HUD_PRINTCONSOLE:
-		auto endpos = strlen(text);
-		if (text[endpos - 1] == '\n')
-			text[endpos - 1] = '\0'; // cut off repeated newline
-
-		spdlog::info(text);
-		break;
-	}
+	std::cout << std::flush;
 }
 
-// clang-format off
-AUTOHOOK(ConCommand_echo, engine.dll + 0x123680,
-void,, (const CCommand& arg))
-// clang-format on
+void CustomSink::custom_log(const custom_log_msg& msg)
 {
-	if (arg.ArgC() >= 2)
-		spdlog::info("[echo] {}", arg.ArgS());
+	std::lock_guard<std::mutex> lock(mutex_);
+	custom_sink_it_(msg);
 }
 
-// This needs to be called after hooks are loaded so we can access the command line args
-void CreateLogFiles()
+void InitialiseConsole()
 {
-	if (strstr(GetCommandLineA(), "-disablelogs"))
+	if (AllocConsole() == FALSE)
 	{
-		spdlog::default_logger()->set_level(spdlog::level::off);
+		std::cout << "[*] Failed to create a console window, maybe a console already exists?" << std::endl;
 	}
 	else
 	{
-		try
-		{
-			// todo: might be good to delete logs that are too old
-			time_t time = std::time(nullptr);
-			tm currentTime = *std::localtime(&time);
-			std::stringstream stream;
+		freopen("CONOUT$", "w", stdout);
+		freopen("CONOUT$", "w", stderr);
+	}
 
-			stream << std::put_time(&currentTime, (GetNorthstarPrefix() + "/logs/nslog%Y-%m-%d %H-%M-%S.txt").c_str());
-			spdlog::default_logger()->sinks().push_back(std::make_shared<spdlog::sinks::basic_file_sink_mt>(stream.str(), false));
-			spdlog::flush_on(spdlog::level::info);
-		}
-		catch (...)
+	// this if statement is adapted from r5sdk
+	if (!strstr(GetCommandLineA(), "-noansiclr"))
+	{
+		g_bSpdLog_UseAnsiColor = true;
+		DWORD dwMode = NULL;
+		HANDLE hOutput = GetStdHandle(STD_OUTPUT_HANDLE);
+
+		GetConsoleMode(hOutput, &dwMode);
+		dwMode |= ENABLE_PROCESSED_OUTPUT | ENABLE_VIRTUAL_TERMINAL_PROCESSING;
+
+		if (!SetConsoleMode(hOutput, dwMode)) // Some editions of Windows have 'VirtualTerminalLevel' disabled by default.
 		{
-			spdlog::error("Failed creating log file!");
-			MessageBoxA(
-				0, "Failed creating log file! Make sure the profile directory is writable.", "Northstar Warning", MB_ICONWARNING | MB_OK);
+			// If 'VirtualTerminalLevel' can't be set, just disable ANSI color, since it wouldnt work anyway.
+			spdlog::warn("could not set VirtualTerminalLevel. Disabling color output");
+			g_bSpdLog_UseAnsiColor = false;
 		}
 	}
 }
 
-void InitialiseLogging()
+void RegisterCustomSink(std::shared_ptr<CustomSink> sink)
 {
-	AllocConsole();
-
-	// Bind stdout to receive console output.
-	// these two lines are responsible for stuff to not show up in the console sometimes, from talking about it on discord
-	// apparently they were meant to make logging work when using -northstar, however from testing it seems that it doesnt
-	// work regardless of these two lines
-	// freopen("CONOUT$", "w", stdout);
-	// freopen("CONOUT$", "w", stderr);
-	spdlog::default_logger()->set_pattern("[%H:%M:%S] [%l] %v");
-}
+	for (auto& logger : loggers)
+	{
+		logger->custom_sinks_.push_back(sink);
+	}
+};
 
-ON_DLL_LOAD_RELIESON("engine.dll", EngineSpewFuncHooks, ConVar, (CModule module))
+void InitialiseLogging()
 {
-	AUTOHOOK_DISPATCH_MODULE(engine.dll)
+	// create a logger, and set it to default
+	NS::log::NORTHSTAR = std::make_shared<ColoredLogger>("NORTHSTAR", NS::Colors::NORTHSTAR, true);
+	NS::log::NORTHSTAR->sinks().clear();
+	loggers.push_back(NS::log::NORTHSTAR);
+	spdlog::set_default_logger(NS::log::NORTHSTAR);
+
+	// create our console sink
+	auto sink = std::make_shared<ExternalConsoleSink>();
+	// set the pattern
+	if (g_bSpdLog_UseAnsiColor)
+		// dont put the log level in the pattern if we are using colours, as the colour will show the log level
+		sink->set_pattern("[%H:%M:%S] [NAME] [LVL] %v");
+	else
+		sink->set_pattern("[%H:%M:%S] [%n] [%l] %v");
 
-	Cvar_spewlog_enable = new ConVar("spewlog_enable", "1", FCVAR_NONE, "Enables/disables whether the engine spewfunc should be logged");
-}
+	// add our sink to the logger
+	NS::log::NORTHSTAR->custom_sinks_.push_back(sink);
 
-ON_DLL_LOAD_CLIENT_RELIESON("client.dll", ClientPrintHooks, ConVar, (CModule module))
-{
-	AUTOHOOK_DISPATCH_MODULE(client.dll)
+	NS::log::SCRIPT_UI = std::make_shared<ColoredLogger>("SCRIPT UI", NS::Colors::SCRIPT_UI);
+	NS::log::SCRIPT_CL = std::make_shared<ColoredLogger>("SCRIPT CL", NS::Colors::SCRIPT_CL);
+	NS::log::SCRIPT_SV = std::make_shared<ColoredLogger>("SCRIPT SV", NS::Colors::SCRIPT_SV);
+
+	NS::log::NATIVE_UI = std::make_shared<ColoredLogger>("NATIVE UI", NS::Colors::NATIVE_UI);
+	NS::log::NATIVE_CL = std::make_shared<ColoredLogger>("NATIVE CL", NS::Colors::NATIVE_CL);
+	NS::log::NATIVE_SV = std::make_shared<ColoredLogger>("NATIVE SV", NS::Colors::NATIVE_SV);
+	NS::log::NATIVE_EN = std::make_shared<ColoredLogger>("NATIVE EN", NS::Colors::NATIVE_ENGINE);
+
+	NS::log::fs = std::make_shared<ColoredLogger>("FILESYSTM", NS::Colors::FILESYSTEM);
+	NS::log::rpak = std::make_shared<ColoredLogger>("RPAK_FSYS", NS::Colors::RPAK);
+	NS::log::echo = std::make_shared<ColoredLogger>("ECHO", NS::Colors::ECHO);
+
+	loggers.push_back(NS::log::SCRIPT_UI);
+	loggers.push_back(NS::log::SCRIPT_CL);
+	loggers.push_back(NS::log::SCRIPT_SV);
+
+	loggers.push_back(NS::log::NATIVE_UI);
+	loggers.push_back(NS::log::NATIVE_CL);
+	loggers.push_back(NS::log::NATIVE_SV);
+	loggers.push_back(NS::log::NATIVE_EN);
 
-	Cvar_cl_showtextmsg = new ConVar("cl_showtextmsg", "1", FCVAR_NONE, "Enable/disable text messages printing on the screen.");
-	pInternalCenterPrint = module.Offset(0x216E940).As<ICenterPrint*>();
+	loggers.push_back(NS::log::fs);
+	loggers.push_back(NS::log::rpak);
+	loggers.push_back(NS::log::echo);
 }