misc: make logging closer to C# and write to file

include/DOF/DOF.h

@@ -2,7 +2,7 @@
 
 #define LIBDOF_VERSION_MAJOR 0 // X Digits
 #define LIBDOF_VERSION_MINOR 4 // Max 2 Digits
-#define LIBDOF_VERSION_PATCH 0 // Max 2 Digits
+#define LIBDOF_VERSION_PATCH 2 // Max 2 Digits
 
 #define _LIBDOF_STR(x) #x
 #define LIBDOF_STR(x) _LIBDOF_STR(x)

src/Log.cpp

@@ -1,27 +1,225 @@
 #include "Log.h"
-
 #include "Logger.h"
+#include "general/StringExtensions.h"
+#include "../include/DOF/DOF.h"
+
+#include <iostream>
+#include <chrono>
+#include <iomanip>
+#include <sstream>
+#include <algorithm>
+#include <filesystem>
 
 namespace DOF
 {
 
-std::string Log::m_filename = "";
-std::unordered_set<std::string> Log::m_onceKeys = {};
+std::ofstream Log::m_logger;
+bool Log::m_isInitialized = false;
+bool Log::m_isOk = false;
+bool Log::m_isEnabled = true;
+std::mutex Log::m_locker;
 
-void Log::Init() { }
-void Log::AfterInit() { }
-void Log::Finish() { }
-void Log::WriteRaw(const char* format, ...) { }
+std::string Log::m_filename = "./DirectOutput.log";
+std::string Log::m_instrumentations = "";
+std::unordered_set<std::string> Log::m_activeInstrumentations;
+std::vector<std::string> Log::m_preLogFileLog;
+std::unordered_set<std::string> Log::m_onceKeys;
 
-void Log::Write(const std::string& message) { ::DOF::Log(DOF_LogLevel_INFO, "%s", message.c_str()); }
+void Log::SetInstrumentations(const std::string& instrumentations)
+{
+   m_instrumentations = instrumentations;
+   if (!instrumentations.empty())
+   {
+      m_activeInstrumentations.clear();
+      std::stringstream ss(instrumentations);
+      std::string item;
+      while (std::getline(ss, item, ','))
+      {
+         item.erase(0, item.find_first_not_of(" \t"));
+         item.erase(item.find_last_not_of(" \t") + 1);
+         if (!item.empty())
+            m_activeInstrumentations.insert(item);
+      }
+   }
+}
+
+void Log::Init(bool enableLogging)
+{
+   std::lock_guard<std::mutex> lock(m_locker);
+   m_isEnabled = enableLogging;
+   if (!m_isInitialized && m_isEnabled)
+   {
+      try
+      {
+         std::filesystem::path logPath(m_filename);
+         if (logPath.has_parent_path())
+         {
+            std::filesystem::create_directories(logPath.parent_path());
+         }
 
-void Log::Warning(const std::string& message) { ::DOF::Log(DOF_LogLevel_WARN, "%s", message.c_str()); }
+         m_logger.open(m_filename, std::ios::app);
+         if (!m_logger.is_open())
+         {
+            m_isOk = false;
+            m_isInitialized = true;
+            return;
+         }
 
-void Log::Error(const std::string& message) { ::DOF::Log(DOF_LogLevel_ERROR, "%s", message.c_str()); }
+         std::string buildConfiguration =
+#ifdef _DEBUG
+            "Debug";
+#else
+            "Release";
+#endif
 
-void Log::Exception(const std::string& message) { ::DOF::Log(DOF_LogLevel_ERROR, "%s", message.c_str()); }
+         std::string instrumentationsEnabledNote = (!m_activeInstrumentations.empty()) ? StringExtensions::Build("; Instrumentations enabled: {0}", m_instrumentations) : "";
 
-void Log::Debug(const std::string& message) { ::DOF::Log(DOF_LogLevel_DEBUG, "%s", message.c_str()); }
+         m_logger << "---------------------------------------------------------------------------------" << std::endl;
+         auto now = std::chrono::system_clock::now();
+         auto time_t = std::chrono::system_clock::to_time_t(now);
+         std::stringstream ss;
+         ss << std::put_time(std::localtime(&time_t), "%Y.%m.%d %H:%M");
+
+         m_logger << StringExtensions::Build("libdof (DirectOutput Framework) - Version {0}, built {1}", LIBDOF_VERSION, ss.str()) << std::endl;
+         m_logger << "DOF created by SwissLizard / MIT License" << std::endl;
+         m_logger << "Original C# version: https://github.com/DirectOutput/DirectOutput" << std::endl;
+         m_logger << "C++ port: https://github.com/jsm174/libdof" << std::endl;
+
+         auto nowMs = std::chrono::system_clock::now();
+         auto timeT = std::chrono::system_clock::to_time_t(nowMs);
+         auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(nowMs.time_since_epoch()) % 1000;
+         std::stringstream timestamp;
+         timestamp << std::put_time(std::localtime(&timeT), "%Y.%m.%d %H:%M:%S");
+         timestamp << "." << std::setfill('0') << std::setw(3) << ms.count();
+
+         m_logger << timestamp.str() << "\t" << StringExtensions::Build("DirectOutput logger initialized{0}", instrumentationsEnabledNote) << std::endl;
+
+         m_isOk = true;
+
+         if (!m_preLogFileLog.empty())
+         {
+            for (const auto& s : m_preLogFileLog)
+               m_logger << s << std::endl;
+
+            m_preLogFileLog.clear();
+         }
+
+         m_logger.flush();
+      }
+      catch (...)
+      {
+         m_isOk = false;
+      }
+
+      m_isInitialized = true;
+   }
+   else if (!m_isInitialized)
+   {
+      m_isInitialized = true;
+      m_isOk = false;
+   }
+}
+
+void Log::AfterInit() { m_preLogFileLog.clear(); }
+
+void Log::Finish()
+{
+   std::lock_guard<std::mutex> lock(m_locker);
+   if (m_logger.is_open())
+   {
+      Write("Logging stopped");
+      m_logger.flush();
+      m_logger.close();
+   }
+   m_isOk = false;
+   m_isInitialized = false;
+   m_isEnabled = true;
+}
+
+void Log::WriteRaw(const std::string& message)
+{
+   std::lock_guard<std::mutex> lock(m_locker);
+   if (!m_isEnabled)
+      return;
+
+   if (m_isOk && m_logger.is_open())
+   {
+      try
+      {
+         m_logger << message << std::endl;
+         m_logger.flush();
+      }
+      catch (...)
+      {
+      }
+   }
+   else if (!m_isInitialized)
+   {
+      m_preLogFileLog.push_back(message);
+   }
+}
+
+void Log::Write(const std::string& message)
+{
+   ::DOF::Log(DOF_LogLevel_INFO, "%s", message.c_str());
+   WriteToFile(message);
+}
+
+void Log::WriteToFile(const std::string& message)
+{
+   if (StringExtensions::IsNullOrWhiteSpace(message))
+   {
+      auto nowMs = std::chrono::system_clock::now();
+      auto timeT = std::chrono::system_clock::to_time_t(nowMs);
+      auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(nowMs.time_since_epoch()) % 1000;
+      std::stringstream timestamp;
+      timestamp << std::put_time(std::localtime(&timeT), "%Y.%m.%d %H:%M:%S");
+      timestamp << "." << std::setfill('0') << std::setw(3) << ms.count();
+      WriteRaw(timestamp.str() + "\t");
+   }
+   else
+   {
+      std::stringstream ss(message);
+      std::string line;
+      while (std::getline(ss, line))
+      {
+         if (!line.empty() && line.back() == '\r')
+            line.pop_back();
+
+         auto nowMs = std::chrono::system_clock::now();
+         auto timeT = std::chrono::system_clock::to_time_t(nowMs);
+         auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(nowMs.time_since_epoch()) % 1000;
+         std::stringstream timestamp;
+         timestamp << std::put_time(std::localtime(&timeT), "%Y.%m.%d %H:%M:%S");
+         timestamp << "." << std::setfill('0') << std::setw(3) << ms.count();
+         WriteRaw(timestamp.str() + "\t" + line);
+      }
+   }
+}
+
+void Log::Error(const std::string& message)
+{
+   ::DOF::Log(DOF_LogLevel_ERROR, "%s", message.c_str());
+   WriteToFile(StringExtensions::Build("Error: {0}", message));
+}
+
+void Log::Warning(const std::string& message)
+{
+   ::DOF::Log(DOF_LogLevel_WARN, "%s", message.c_str());
+   WriteToFile(StringExtensions::Build("Warning: {0}", message));
+}
+
+void Log::Exception(const std::string& message)
+{
+   ::DOF::Log(DOF_LogLevel_ERROR, "%s", message.c_str());
+   WriteToFile(StringExtensions::Build("EXCEPTION: {0}", message));
+}
+
+void Log::Debug(const std::string& message)
+{
+   ::DOF::Log(DOF_LogLevel_DEBUG, "%s", message.c_str());
+   WriteToFile(StringExtensions::Build("Debug: {0}", message));
+}
 
 void Log::Once(const std::string& key, const std::string& message)
 {
@@ -32,8 +230,30 @@ void Log::Once(const std::string& key, const std::string& message)
    }
 }
 
-void Log::Instrumentation(const std::string& key, const std::string& message) { Debug(message); }
+void Log::Instrumentation(const std::string& key, const std::string& message)
+{
+   bool writeMessage = m_activeInstrumentations.find("*") != m_activeInstrumentations.end();
+   if (!writeMessage)
+   {
+      std::stringstream ss(key);
+      std::string keyItem;
+      bool allKeysFound = true;
+
+      while (std::getline(ss, keyItem, ',') && allKeysFound)
+      {
+         keyItem.erase(0, keyItem.find_first_not_of(" \t"));
+         keyItem.erase(keyItem.find_last_not_of(" \t") + 1);
+         if (m_activeInstrumentations.find(keyItem) == m_activeInstrumentations.end())
+            allKeysFound = false;
+      }
+      writeMessage = allKeysFound;
+   }
 
-Log::Log() { }
+   if (writeMessage)
+   {
+      ::DOF::Log(DOF_LogLevel_DEBUG, "%s", message.c_str());
+      WriteToFile(StringExtensions::Build("Debug [{0}]: {1}", key, message));
+   }
+}
 
 }

src/Log.h

@@ -2,23 +2,28 @@
 
 #include "DOF/DOF.h"
 #include <unordered_set>
+#include <vector>
+#include <fstream>
+#include <mutex>
 
 namespace DOF
 {
 
 class Log
 {
 public:
-   static const std::string& GetFilename();
+   static const std::string& GetFilename() { return m_filename; }
    static void SetFilename(const std::string& filename) { m_filename = filename; }
 
-   static void Init();
+   static std::string GetInstrumentations() { return m_instrumentations; }
+   static void SetInstrumentations(const std::string& instrumentations);
+
+   static void Init(bool enableLogging = true);
    static void AfterInit();
    static void Finish();
-   static void WriteRaw(const char* format, ...);
    static void Write(const std::string& message);
-   static void Warning(const std::string& message);
    static void Error(const std::string& message);
+   static void Warning(const std::string& message);
    static void Exception(const std::string& message);
    static void Debug(const std::string& message);
    static void Once(const std::string& key, const std::string& message);
@@ -28,7 +33,19 @@ class Log
    Log();
    ~Log() { };
 
+   static void WriteRaw(const std::string& message);
+   static void WriteToFile(const std::string& message);
+
+   static std::ofstream m_logger;
+   static bool m_isInitialized;
+   static bool m_isOk;
+   static bool m_isEnabled;
+   static std::mutex m_locker;
+
    static std::string m_filename;
+   static std::string m_instrumentations;
+   static std::unordered_set<std::string> m_activeInstrumentations;
+   static std::vector<std::string> m_preLogFileLog;
    static std::unordered_set<std::string> m_onceKeys;
 };
 

src/Pinball.cpp

@@ -82,9 +82,12 @@ void Pinball::Setup(const std::string& globalConfigFileName, const std::string&
       throw std::runtime_error("DirectOutput framework could not initialize global config.");
    }
 
-   if (m_globalConfig->IsEnableLogging())
+   try
    {
-      if (m_globalConfig->IsClearLogOnSessionStart())
+      Log::SetFilename(m_globalConfig->GetLogFilename(!StringExtensions::IsNullOrWhiteSpace(tableFilename) ? FileInfo(tableFilename).FullName() : "", romName));
+      Log::SetInstrumentations(m_globalConfig->GetInstrumentation());
+
+      if (m_globalConfig->IsEnableLogging() && m_globalConfig->IsClearLogOnSessionStart())
       {
          try
          {
@@ -97,15 +100,12 @@ void Pinball::Setup(const std::string& globalConfigFileName, const std::string&
          {
          }
       }
-      try
-      {
-         Log::SetFilename(m_globalConfig->GetLogFilename(!StringExtensions::IsNullOrWhiteSpace(tableFilename) ? FileInfo(tableFilename).FullName() : "", romName));
-         Log::Init();
-      }
-      catch (const std::exception& e)
-      {
-         throw std::runtime_error("DirectOutput framework could initialize the log file.");
-      }
+
+      Log::Init(m_globalConfig->IsEnableLogging());
+   }
+   catch (const std::exception& e)
+   {
+      throw std::runtime_error("DirectOutput framework could initialize the log file.");
    }
 
    Log::AfterInit();