Issue #1234, #2058 - Rewrite log facility, improving thread implementation

src/plugin/PluginDebug.cpp

Index: src/plugin/PluginDebug.cpp
===================================================================
--- a/src/plugin/PluginDebug.cpp
+++ b/src/plugin/PluginDebug.cpp
@@ -17,13 +17,24 @@
 
 #include "PluginStdAfx.h"
 #include "PluginDebug.h"
-#include "PluginClientBase.h"
+#include "ActiveQueue.h"
 #include "PluginMutex.h"
-#include "PluginClientBase.h"
 #include "../shared/Utils.h"
+#include <Windows.h>
 #include <iomanip>
 #include <memory>
 
+namespace Trace
+{
+  Location::Location(int id, int subId)
+    : prefixText()
+  {
+    std::ostringstream ss;
+    ss << "ErrorCode(" << id << "," << subId << ")";
+    postfixText = ss.str();
+  };
+}
+
 namespace
 {
   class CPluginDebugLock
@@ -47,6 +58,9 @@
 
   CComAutoCriticalSection CPluginDebugLock::s_criticalSectionDebugLock;
 
+  /**
+   * The polymorphic part of a log entry.
+   */
   class LogText
   {
   public:
@@ -107,9 +121,14 @@
     }
   };
 
+  /**
+   * Standard log entry, with variation in the data that generates the log message.
+   */
   class LogEntry
   {
-    const std::unique_ptr<LogText> text;
+    std::unique_ptr<LogText> text;
+
+    const Trace::Location location;
 
     std::string InitialPrefix() const
     {
@@ -148,14 +167,27 @@
      */
     const DWORD threadId;
 
-    explicit LogEntry(LogText* text)
-      : processId(::GetCurrentProcessId()), threadId(::GetCurrentThreadId()), text(text)
+    explicit LogEntry(LogText* text, Trace::Location location)
+      : text(text), location(location), processId(::GetCurrentProcessId()), threadId(::GetCurrentThreadId())
     {}
 
-    LogEntry(LogText* text, DWORD processId, DWORD threadId)
-      : processId(processId), threadId(threadId), text(text)
+    /**
+     * Move constructor transfers 'text', copies everything else.
+     */
+    LogEntry(LogEntry&& x)
+      : text(std::move(x.text)), location(x.location), st(x.st), processId(x.processId), threadId(x.threadId)
     {}
 
+    /**
+     * Copy constructor deleted.
+     */
+    LogEntry(const LogEntry&); // = delete
+
+    /**
+     * Copy assignment deleted.
+     */
+    LogEntry& operator=(const LogEntry&); // = delete
+
     void Write(std::ostream& out) const
     {
       CPluginDebugLock lock;
@@ -165,19 +197,49 @@
         size_t linePosition = 0;
         while (true)
         {
-          auto eolPosition = lines.find('\n', linePosition);
+          // Standard prefix, timestamp and thread ID
           auto prefix = linePosition == 0 ? InitialPrefix() : SubsequentPrefix();
           out << prefix;
+
+          // Location prefix, if any
+          if (location.prefixText.length() > 0)
+          {
+            out << location.prefixText << " - ";
+          }
+
+          // One line of the log text itself
+          auto eolPosition = lines.find('\n', linePosition);
           if (eolPosition == std::string::npos)
           {
-            out << lines.substr(linePosition) << "\n";
-            break;
+            out << lines.substr(linePosition);
           }
           else
           {
-            out << lines.substr(linePosition, eolPosition - linePosition) << "\n";
+            out << lines.substr(linePosition, eolPosition - linePosition);
             linePosition = eolPosition + 1;
           }
+
+          // Location postfix, if any
+          if (location.postfixText.length() > 0)
+          {
+            out << " - ";
+            // Hack to deal with how gyp generates file names for Visual Studio
+            if (location.postfixText.find("..\\..\\") == 0)
+            {
+              out << location.postfixText.substr(6);
+            }
+            else
+            {
+              out << location.postfixText;
+            }
+          }
+          out << "\n";
+
+          // Check to see if that was the last line
+          if (eolPosition == std::string::npos)
+          {
+            break;
+          }
         }
         out.flush();
       }
@@ -208,12 +270,97 @@
     le.WriteFile(debugFileName);
   }
 }
-  
+
+/**
+ * An active queue of 'LogEntry'.
+ * Life cycle is maintained in conjunction with 'LogQueueReference'.
+ */
+class LogQueue
+{
+  /**
+   * Processor for the log queue
+   */
+  static void ProcessLogEntry(const LogEntry&);
+
+  /**
+   * Active queue for processing log entries.
+   */
+  ActiveQueue<LogEntry, decltype(ProcessLogEntry)> queue;
+
+public:
+  /**
+   * Insert an item into the queue.
+   */
+  static void Insert(LogEntry&& t)
+  {
+    /*
+     * Note that this function(indeed, this class) does not have the
+     *   responsibility to ensure that an instance of the queue exists.
+     * See 'LogQueueReference' for the class that does.
+     * The non-null guard here is purely defensive;
+     *   we shouldn't ever lose queued events because of it.
+     */
+    if (LogQueueReference::queueMasterReference)
+    {
+      LogQueueReference::queueMasterReference->queue.Insert(std::move(t));
+    }
+  }
+
+  LogQueue()
+    : queue(ProcessLogEntry)
+  {}
+};
+
+/**
+ * The processor for the log queue simply writes each log entry to its corresponding log file.
+ *
+ * At present the only log entries that go through the queue also go to the default log file.
+ * This logic will expand to include other log files as we pass all the log entries through the queue.
+ */
+void LogQueue::ProcessLogEntry(const LogEntry& entry)
+{
+  LogWriteDefault(entry);
+}
+
+/*
+ * Static initializations
+ */
+LogQueueReference::pointer LogQueueReference::queueMasterReference;
+std::mutex LogQueueReference::mutex;
+
+/*
+ * Only initialize the instance reference within the constructor body,
+ *   so that it's serialized under the protection of the mutex.
+ */
+LogQueueReference::LogQueueReference()
+  : queueReference(queueMasterReference)
+{
+  std::unique_lock<std::mutex> lock(LogQueueReference::mutex);
+  if (!queueMasterReference)
+  {
+    queueMasterReference = pointer(new LogQueue());
+    LogQueue::Insert(LogEntry(new LogTextFixed("LogQueue start"), HERE_F));
+  }
+  queueReference = queueMasterReference;
+}
+
+LogQueueReference::~LogQueueReference()
+{
+  std::unique_lock<std::mutex> lock(LogQueueReference::mutex);
+  queueReference.reset();
+  if (queueMasterReference.use_count() == 1)
+  {
+    LogQueue::Insert(LogEntry(new LogTextFixed("LogQueue stop"), HERE_F));
+    queueMasterReference.reset();
+  }
+}
+
+
 #ifdef ENABLE_DEBUG_INFO
 
 void CPluginDebug::Debug(const std::string& text)
 {
-  LogWriteDefault(LogEntry(new LogTextFixed(text)));
+  LogWriteDefault(LogEntry(new LogTextFixed(text), Trace::Location()));
 }
 
 void CPluginDebug::Debug(const std::wstring& text)
@@ -223,38 +370,29 @@
 
 #endif
 
-void CPluginDebug::DebugSystemException(const std::system_error& ex, int errorId, int errorSubid, const std::string& description)
+namespace Trace
 {
-  std::string message = description + ", " + ex.code().message() + ", " + ex.what();
-  DEBUG_ERROR_LOG(ex.code().value(), errorId, errorSubid, message);
+  void SystemException(const std::system_error& ex, const std::string& description, Trace::Location location)
+  {
+    std::string message = description + ", " + ex.code().message() + ", " + ex.what();
+    ErrorCode(ex.code().value(), message, location);
+  }
 }
 
 #if (defined ENABLE_DEBUG_INFO)
 
-void CPluginDebug::DebugException(const std::exception& ex)
+void CPluginDebug::DebugException(const std::exception& ex, Trace::Location location)
 {
   auto lt = new LogTextFixed(ex);
-  LogEntry le(lt);
-#ifdef ENABLE_DEBUG_ERROR
+  LogEntry le(lt, location);
   LogWriteDefault(le);
-#endif
-  DEBUG_SELFTEST(
-    "********************************************************************************\n"
-    + lt->text() + "\n"
-    "********************************************************************************")
 }
 
-void CPluginDebug::DebugErrorCode(DWORD errorCode, const std::string& error, DWORD processId, DWORD threadId)
+void CPluginDebug::DebugErrorCode(DWORD errorCode, const std::string& error, Trace::Location location)
 {
   auto lt = new LogTextErrorCode(errorCode, error);
-  LogEntry le(lt, processId, threadId);
-#ifdef ENABLE_DEBUG_ERROR
+  LogEntry le(lt, location);
   LogWriteDefault(le);
-#endif
-  DEBUG_SELFTEST(
-    "********************************************************************************\n"
-    + lt->text() + "\n"
-    "********************************************************************************")
 }
 
 #endif
@@ -267,7 +405,7 @@
 
 void CPluginDebug::DebugResult(const std::wstring& text)
 {
-  LogWriteResult(LogEntry(new LogTextFixed(ToUtf8String(text))));
+  LogWriteResult(LogEntry(new LogTextFixed(ToUtf8String(text)), Trace::Location()));
 }
 
 void CPluginDebug::DebugResultDomain(const std::wstring& domain)
@@ -306,7 +444,6 @@
   DebugResultFormat(L"Blocked", type, domain.empty() ? L"-" : domain, Shorten(src));
 }
 
-
 void CPluginDebug::DebugResultHiding(const std::wstring& tag, const std::wstring& id, const std::wstring& filter)
 {
   DebugResultFormat(L"Hidden", tag, L"- " + Shorten(id), filter);
@@ -314,7 +451,6 @@
 
 #endif // ENABLE_DEBUG_RESULT
 
-
 #ifdef ENABLE_DEBUG_RESULT_IGNORED
 
 void CPluginDebug::DebugResultIgnoring(const std::wstring& type, const std::wstring& src, const std::wstring& domain)
@@ -323,3 +459,13 @@
 }
 
 #endif // ENABLE_DEBUG_RESULT_IGNORED
+
+void Trace::ErrorCode(DWORD errorCode, const std::string& description, Trace::Location location)
+{
+  LogQueue::Insert(LogEntry(new LogTextErrorCode(errorCode, description), location));
+}
+
+void Trace::TextFixed(const std::string& description, Trace::Location location)
+{
+  LogQueue::Insert(LogEntry(new LogTextFixed(description), location));
+}