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

src/plugin/PluginDebug.cpp

 /*
  * This file is part of Adblock Plus <https://adblockplus.org/>,
  * Copyright (C) 2006-2016 Eyeo GmbH
  *
  * Adblock Plus is free software: you can redistribute it and/or modify
  * it under the terms of the GNU General Public License version 3 as
  * published by the Free Software Foundation.
  *
  * Adblock Plus is distributed in the hope that it will be useful,
  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  * GNU General Public License for more details.
  *
  * You should have received a copy of the GNU General Public License
  * along with Adblock Plus.  If not, see <http://www.gnu.org/licenses/>.
  */
 
 #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
     : public CPluginMutex
   {
   private:
     static CComAutoCriticalSection s_criticalSectionDebugLock;
 
   public:
     CPluginDebugLock()
       : CPluginMutex(L"DebugFile", PLUGIN_ERROR_MUTEX_DEBUG_FILE)
     {
       s_criticalSectionDebugLock.Lock();
     }
 
     ~CPluginDebugLock()
     {
       s_criticalSectionDebugLock.Unlock();
     }
   };
 
   CComAutoCriticalSection CPluginDebugLock::s_criticalSectionDebugLock;
 
+  /**
+   * The polymorphic part of a log entry.
+   */
   class LogText
   {
   public:
     virtual std::string Text() const = 0;
     virtual ~LogText() {};
   };
 
   class LogTextFixed
     : public LogText
   {
@@ skipping 41 matching lines @@
    */
   struct SystemTime
     : public SYSTEMTIME
   {
     SystemTime()
     {
       ::GetSystemTime(static_cast<SYSTEMTIME*>(this));
     }
   };
 
+  /**
+   * 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
     {
       std::stringstream ss;
       ss << std::setfill('0') << std::setw(2) << st.wHour;
       ss << ":";
       ss << std::setfill('0') << std::setw(2) << st.wMinute;
       ss << ":";
       ss << std::setfill('0') << std::setw(2) << st.wSecond;
       ss << ".";
@@ skipping 18 matching lines @@
     /**
      * The process within which the log-generating statement executes.
      */
     const DWORD processId;
 
     /**
      * The thread within which the log-generating statement executes.
      */
     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;
       if (lock.IsLocked())
       {
         auto lines = text->Text();
         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();
       }
     }
 
     void WriteFile(const std::wstring& logFileName) const
     {
       std::ofstream out;
       out.open(logFileName, std::ios::app);
       Write(out);
@@ skipping 10 matching lines @@
     std::wstring debugFileName = GetDataPath(L"debug_" + std::to_wstring(le.processId) + L".txt");
     le.WriteFile(debugFileName);
   }
 
   void LogWriteResult(const LogEntry& le)
   {
     std::wstring debugFileName = GetDataPath(L"debug_result.txt");
     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)
 {
   Debug(ToUtf8String(text));
 }
 
 #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
 
 // ============================================================================
 // Debug result
 // ============================================================================
 
 #ifdef ENABLE_DEBUG_RESULT
 
 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)
 {
   DebugResult(
     L"=========================================================================================\n"
     + domain + L"\n"
     L"=========================================================================================");
 }
 
@@ skipping 18 matching lines @@
     r += s.substr(n - 30, 30);
     return r;
   }
 }
 
 void CPluginDebug::DebugResultBlocking(const std::wstring& type, const std::wstring& src, const std::wstring& domain)
 {
   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);
 }
 
 #endif // ENABLE_DEBUG_RESULT
 
-
 #ifdef ENABLE_DEBUG_RESULT_IGNORED
 
 void CPluginDebug::DebugResultIgnoring(const std::wstring& type, const std::wstring& src, const std::wstring& domain)
 {
   DebugResultFormat(L"Ignored", type, domain.empty() ? L"-" : domain, Shorten(src));
 }
 
 #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));
+}
+
 namespace
 {
   /*
    * To convert a pointer to a hexadecimal number, we need an integral type that has the same size as that of the pointer.
    */
 #if defined(_WIN64)
   typedef uint64_t voidIntegral;
   static_assert(sizeof(void*)==sizeof(voidIntegral),"WIN64: sizeof(uint64_t) is not the same as sizeof(void*)");
 #elif defined(_WIN32)
   typedef uint32_t voidIntegral;
   static_assert(sizeof(void*)==sizeof(voidIntegral),"WIN32: sizeof(uint32_t) is not the same as sizeof(void*)");
 #else
 #error Must compile with either _WIN32 or _WIN64
 #endif
 }
 
 std::wstring ToHexLiteral(void const* p)
 {
   std::wstringstream ss;
   ss << L"0x";
   ss.width(sizeof(p) * 2);
   ss.fill(L'0');
   ss << std::hex << reinterpret_cast<voidIntegral>(p);
   return ss.str();
 }