Issue #1234 - Rewrite internals of debug facility

src/plugin/PluginDebug.cpp

Index: src/plugin/PluginDebug.cpp
===================================================================
--- a/src/plugin/PluginDebug.cpp
+++ b/src/plugin/PluginDebug.cpp
@@ -19,148 +19,242 @@
 #include "PluginDebug.h"
 #include "PluginClientBase.h"
 #include "PluginMutex.h"
-#include "PluginSettings.h"
+#include "PluginClientBase.h"
+#include "../shared/Utils.h"
+#include <iomanip>
+#include <memory>
 
-class CPluginDebugLock : public CPluginMutex
+namespace
 {
+  class CPluginDebugLock
+    : public CPluginMutex
+  {
+  private:
+    static CComAutoCriticalSection s_criticalSectionDebugLock;

[sergei, 2015/10/12 12:46:20]

What will happen if we remove `s_criticalSectionDebugLock`?

[Eric, 2015/10/13 17:33:19]

The problem right now (and also in the later version with an active queue
processing the messages) is that we are writing to log files both (1) directly
in-line when called and (2) indirectly through a queue, both in the old version
(which is still being used in the code for this patch set) and the new version
(subsequent patch set). This semaphore is being used to serialize writing to the
log files. If we didn't do that, we could see occasional interleaving of message
text when there was a context switch during a file write operation.

My plan is to eliminate this class and all of its uses. Once we get logging
working through the active queue, we can convert the log messages, of all kinds,
to _all_ go through the queue. Once that's done, all the file I/O will be in the
worker thread of the active queue. It will be implicitly serialized and there
will be no possible race conditions between multiple threads trying to write to
log files. 

This method, in addition, has a performance benefit. Right now, we're using
synchronous, blocking disk I/O in all the BHO functions we provide. Getting them
out of the execution path will improve call times as IE sees them. Admittedly
this mostly applies right now in Debug compiles, and only for trace and debug
messages, but there's some monitoring in Release builds we can use this for
later where it will matter much more.

This change isn't in the present change set, nor then next one, simply to keep
the sizes of the change set as small as feasible.

[sergei, 2015/11/30 14:15:03]

The plan is clear but the reason we need `s_criticalSectionDebugLock` is not
clear. I think we can safely get rid of it. It's used only inside
`CPluginDebugLock` which firstly obtains a lock using named mutex
(`CPluginMutex`) and then it calls `s_criticalSectionDebugLock.Lock()`. In the
destructor it calls firstly `s_criticalSectionDebugLock.Unlock();` and then
releases `CPluginMutex`. `s_criticalSectionDebugLock.Lock()` does not ever wait
thus does not serialize an access to anything.

[Eric, 2015/11/30 17:39:01]

There's only one occurrence of 'CPluginDebugLock', but it's a sentry object in
'Write()' below. As a sentry object, it calls the constructor at the point of
declaration. It calls the destructor at the end of the body of 'Write()' when it
goes out of scope. The critical section will lock if there's another thread
currently in a call to 'Write()'.

We can't get rid of the 's_criticalSectionDebugLock' until we don't need that
sentry object any more, that is, until after all the calls to 'Write()' occur in
a single thread. At that point 'CPluginDebugLock' can go away along with all it
entrains.

[sergei, 2015/11/30 18:14:29]

There is already CPluginMutex and it serializes the access to the file
system-wise, it does not matter whether Write is called from different threads
of one process of of many processes, the access is serialized by CPluginMutex.
s_criticalSectionDebugLock does not wait for anything.

[Eric, 2015/12/01 20:43:57]

Now I see what you're getting at. Yes, the critical section is redundant.

Removing it though, would be out of scope for this change set. This is,
notionally, about removing CString, although I did that by reworking the string
handling wholesale. CPluginDebugLock is unaltered from the previous version
except for reformatting. The next change set, already up for review, reworks the
threading etc. and would be the right place to make this change. Please remind
me again there if I forget.

[sergei, 2015/12/02 13:52:59]

Acknowledged.

 
-private:
+  public:
+    CPluginDebugLock()
+      : CPluginMutex(L"DebugFile", PLUGIN_ERROR_MUTEX_DEBUG_FILE)
+    {
+      s_criticalSectionDebugLock.Lock();
+    }
 
-  static CComAutoCriticalSection s_criticalSectionDebugLock;
+    ~CPluginDebugLock()
+    {
+      s_criticalSectionDebugLock.Unlock();
+    }
+  };
 
-public:
+  CComAutoCriticalSection CPluginDebugLock::s_criticalSectionDebugLock;
 
-  CPluginDebugLock() : CPluginMutex(L"DebugFile", PLUGIN_ERROR_MUTEX_DEBUG_FILE)
+  class LogText

[sergei, 2015/10/12 12:46:20]

virtual destructor is missed here, the derived classes will leak.

[Eric, 2015/10/13 17:33:19]

Yep. I'll add it after I get a rebase posted.

   {
-    s_criticalSectionDebugLock.Lock();
+  public:
+    virtual std::string Text() const = 0;
+  };
+
+  class LogTextFixed
+    : public LogText
+  {
+  protected:
+    const std::string fixedText;
+
+  public:
+    explicit LogTextFixed(const std::string& text)
+      : fixedText(text)
+    {}
+
+    explicit LogTextFixed(const std::exception& ex)
+      : fixedText(std::string("!!! Exception: ") + ex.what())
+    {}
+
+    virtual std::string Text() const override
+    {
+      return fixedText;
+    }
+  };
+
+  class LogTextErrorCode
+    : public LogTextFixed
+  {
+  protected:
+    const DWORD errorCode;
+
+  public:
+    LogTextErrorCode(DWORD errorCode, const std::string& text)
+      : LogTextFixed(text), errorCode(errorCode)
+    {}
+
+    virtual std::string Text() const override
+    {
+      std::ostringstream ss;
+      ss << fixedText << ". error = " << errorCode << " (0x";
+      ss << std::setfill('0') << std::setw(2 * sizeof(DWORD)) << std::hex << errorCode;
+      ss << ")";
+      return ss.str();
+    }
+  };
+
+  /**
+   * Wrapper around SYSTEMTIME allows initialization of 'const' instances.
+   */
+  struct SystemTime
+    : public SYSTEMTIME
+  {
+    SystemTime()
+    {
+      ::GetSystemTime(static_cast<SYSTEMTIME*>(this));
+    }
+  };
+
+  class LogEntry
+  {
+    const std::unique_ptr<LogText> text;
+
+    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 << ".";
+      ss << std::setfill('0') << std::setw(3) << st.wMilliseconds;
+      ss << " [";
+      ss << std::setfill(' ') << std::setw(5) << threadId;
+      ss << "] - ";
+      return ss.str();
+    }
+
+    std::string SubsequentPrefix() const
+    {
+      return "                     + ";
+    }
+
+  public:
+    /**
+     * The time at which the log-generating statement executes.
+     */
+    const SystemTime st;
+
+    /**
+     * 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)
+    {}
+
+    LogEntry(LogText* text, DWORD processId, DWORD threadId)
+      : processId(processId), threadId(threadId), text(text)
+    {}
+
+    void Write(std::ostream& out) const
+    {
+      CPluginDebugLock lock;

[Eric, 2015/11/30 17:39:01]

This is the sentry object.

'Write()' is currently called from multiple threads.

+      if (lock.IsLocked())
+      {
+        auto lines = text->Text();
+        size_t linePosition = 0;
+        while (true)
+        {
+          auto eolPosition = lines.find('\n', linePosition);
+          auto prefix = linePosition == 0 ? InitialPrefix() : SubsequentPrefix();
+          out << prefix;
+          if (eolPosition == std::string::npos)
+          {
+            out << lines.substr(linePosition) << "\n";
+            break;
+          }
+          else
+          {
+            out << lines.substr(linePosition, eolPosition - linePosition) << "\n";
+            linePosition = eolPosition + 1;
+          }
+        }
+        out.flush();
+      }
+    }
+
+    void WriteFile(const std::wstring& logFileName) const
+    {
+      std::ofstream out;
+      out.open(logFileName, std::ios::app);
+      Write(out);
+    }
+  };
+
+  std::wstring GetDataPath(const std::wstring& filename)
+  {
+    return GetAppDataPath() + L"\\" + filename;
   }
 
-  ~CPluginDebugLock()
+  void LogWriteDefault(const LogEntry& le)
   {
-    s_criticalSectionDebugLock.Unlock();
+    std::wstring debugFileName = GetDataPath(L"debug_" + std::to_wstring(le.processId) + L".txt");
+    le.WriteFile(debugFileName);
   }
-};
 
-CComAutoCriticalSection CPluginDebugLock::s_criticalSectionDebugLock;
+  void LogWriteResult(const LogEntry& le)
+  {
+    std::wstring debugFileName = GetDataPath(L"debug_result.txt");
+    le.WriteFile(debugFileName);
+  }
+}
+  
+#ifdef ENABLE_DEBUG_INFO
+
+void CPluginDebug::Debug(const std::string& text)
+{
+  LogWriteDefault(LogEntry(new LogTextFixed(text)));
+}
+
+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)
 {
-  std::string message = description + ", " + ex.code().message() + ", " + ex.what();
-  DEBUG_ERROR_LOG(ex.code().value(), errorId, errorSubid, message);
+  std::string message = description + ", " + ex.code().message() + ", " + ex.what();
+  DEBUG_ERROR_LOG(ex.code().value(), errorId, errorSubid, message);
 }
 
-#ifdef ENABLE_DEBUG_INFO
-
-void DebugLegacy(const CString& text, DWORD dwProcessId, DWORD dwThreadId)
-{
-#ifdef USE_CONSOLE
-  CONSOLE("%s", CT2A(text.GetString(), CP_UTF8));
-#endif
-
-  if (CPluginSettings::HasInstance())
-  {
-#ifdef ENABLE_DEBUG_SPLIT_FILE
-    CPluginSettings* settings = CPluginSettings::GetInstance();
-
-    bool isWorkingThread = settings->IsWorkingThread(dwThreadId);
-
-    std::wstring processor;
-    wchar_t tmp[10];
-    _itow_s(::GetCurrentProcessId(), tmp, 10);
-    if (isWorkingThread)
-      processor = L"tab" + std::wstring(tmp) + L"_thread";
-    else
-      processor = L"tab" + std::wstring(tmp) + L"_ui";
-#else
-    if (dwProcessId == 0)
-    {
-      dwProcessId = ::GetCurrentProcessId();
-    }
-    if (dwThreadId == 0)
-    {
-      dwThreadId = ::GetCurrentThreadId();
-    }
-
-    CStringA processInfo;
-    processInfo.Format("%4.4u.%4.4u - ", dwProcessId, dwThreadId);
-#endif
-    SYSTEMTIME st;
-    ::GetSystemTime(&st);
-
-    CStringA sysTime;
-    sysTime.Format("%2.2d:%2.2d:%2.2d.%3.3d - ", st.wHour, st.wMinute, st.wSecond, st.wMilliseconds);
-
-    CPluginDebugLock lock;
-    if (lock.IsLocked())
-    {
-      std::ofstream debugFile;
-
-#ifdef ENABLE_DEBUG_SPLIT_FILE
-      debugFile.open(GetDataPath(L"debug_" + processor + L".txt"), std::ios::app);
-#else
-      debugFile.open(GetDataPath(L"debug.txt"), std::ios::app);
-#endif
-      int pos = 0;
-      CStringA line = text.Tokenize(L"\n\r", pos);
-
-      while (pos >= 0)
-      {
-        debugFile.write(sysTime.GetBuffer(), sysTime.GetLength());
-#ifndef ENABLE_DEBUG_SPLIT_FILE
-        debugFile.write(processInfo.GetBuffer(), processInfo.GetLength());
-#endif
-        debugFile.write(line.GetBuffer(), line.GetLength());
-        debugFile.write("\n", 1);
-
-        line = text.Tokenize(L"\n\r", pos);
-      }
-
-      debugFile.flush();
-    }
-  }
-}
-
-void CPluginDebug::Debug(const std::string& text, DWORD processId, DWORD threadId)
-{
-  DebugLegacy(CString(text.c_str()), processId, threadId);
-}
-
-void CPluginDebug::Debug(const std::wstring& text, DWORD processId, DWORD threadId)
-{
-  DebugLegacy(ToCString(text), processId, threadId);
-}
-
-#endif
-
 #if (defined ENABLE_DEBUG_INFO)
 
 void CPluginDebug::DebugException(const std::exception& ex)
 {
-  auto error = std::string("!!! Exception:") + ex.what();
+  auto lt = new LogTextFixed(ex);
+  LogEntry le(lt);
 #ifdef ENABLE_DEBUG_ERROR
-  Debug(error);
+  LogWriteDefault(le);
 #endif
-
-  DEBUG_SELFTEST("********************************************************************************\n" + error + "\n********************************************************************************")
-}
-
-void DebugErrorCodeLegacy(DWORD errorCode, const CString& error, DWORD dwProcessId, DWORD dwThreadId)
-{
-  CString errorCodeText;
-  errorCodeText.Format(L"%u (0x%8.8x)", errorCode, errorCode);
-
-  CString finalError = error + L". error=" + errorCodeText;
-
-#ifdef ENABLE_DEBUG_ERROR
-  DebugLegacy(finalError, dwProcessId, dwThreadId);
-#endif
-
-  DEBUG_SELFTEST(L"********************************************************************************\n" + finalError + "\n********************************************************************************")
+  DEBUG_SELFTEST(
+    "********************************************************************************\n"
+    + lt->text() + "\n"
+    "********************************************************************************")
 }
 
 void CPluginDebug::DebugErrorCode(DWORD errorCode, const std::string& error, DWORD processId, DWORD threadId)
 {
-  DebugErrorCodeLegacy(errorCode, CString(error.c_str()), processId, threadId);
+  auto lt = new LogTextErrorCode(errorCode, error);
+  LogEntry le(lt, processId, threadId);
+#ifdef ENABLE_DEBUG_ERROR
+  LogWriteDefault(le);
+#endif
+  DEBUG_SELFTEST(
+    "********************************************************************************\n"
+    + lt->text() + "\n"
+    "********************************************************************************")
 }
 
 #endif
@@ -171,69 +265,51 @@
 
 #ifdef ENABLE_DEBUG_RESULT
 
-void DebugResultLegacy(const CString& text)
-{
-  SYSTEMTIME st;
-  ::GetSystemTime(&st);
-
-  CStringA sysTime;
-  sysTime.Format("%2.2d:%2.2d:%2.2d.%3.3d - ", st.wHour, st.wMinute, st.wSecond, st.wMilliseconds);
-
-  CStringA textA = text;
-
-  CPluginDebugLock lock;
-  if (lock.IsLocked())
-  {
-    std::ofstream debugFile;
-
-    debugFile.open(GetDataPath(L"debug_result.txt"), std::ios::app);
-    debugFile.write(sysTime.GetBuffer(), sysTime.GetLength());
-    debugFile.write(LPCSTR(textA), textA.GetLength());
-    debugFile.write("\n", 1);
-    debugFile.flush();
-  }
-}
-
 void CPluginDebug::DebugResult(const std::wstring& text)
 {
-  DebugResultLegacy(ToCString(text));
+  LogWriteResult(LogEntry(new LogTextFixed(ToUtf8String(text))));
 }
 
 void CPluginDebug::DebugResultDomain(const std::wstring& domain)
 {
-  DebugResult(L"===========================================================================================================================================================================================");
-  DebugResult(domain);
-  DebugResult(L"===========================================================================================================================================================================================");
+  DebugResult(
+    L"=========================================================================================\n"
+    + domain + L"\n"
+    L"=========================================================================================");
 }
 
+namespace
+{
+  void DebugResultFormat(const std::wstring& action, const std::wstring& type, const std::wstring& param1, const std::wstring& param2)
+  {
+    std::wostringstream ss;
+    ss << std::setw(7) << std::setiosflags(std::ios::left) << action;
+    ss << L"  ";
+    ss << std::setw(12) << std::setiosflags(std::ios::left) << type;
+    ss << L"  " << param1 << L"  " << param2;
+    CPluginDebug::DebugResult(ss.str());
+  }
+
+  std::wstring Shorten(const std::wstring& s)
+  {
+    auto n = s.length();
+    if (n <= 100) return s;
+    auto r = s.substr(0, 67);
+    r += L"...";
+    r += s.substr(n - 30, 30);
+    return r;
+  }
+}
 
 void CPluginDebug::DebugResultBlocking(const std::wstring& type, const std::wstring& src, const std::wstring& domain)
 {
-  CString srcTrunc = ToCString(src);
-  if (src.length() > 100)
-  {
-    srcTrunc = srcTrunc.Left(67) + L"..." + srcTrunc.Right(30);
-  }
-
-  CString blocking;
-  blocking.Format(L"Blocked  %-12s  %-20s  %s", ToCString(type), domain.empty()? L"-" : ToCString(domain), srcTrunc);
-
-  DebugResultLegacy(blocking);
+  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)
 {
-  CString srcTrunc = ToCString(id);
-  if (srcTrunc.GetLength() > 100)
-  {
-    srcTrunc = srcTrunc.Left(67) + L"..." + srcTrunc.Right(30);
-  }
-
-  CString blocking;
-  blocking.Format(L"Hidden   %-12s  - %s  %s", ToCString(tag), srcTrunc, ToCString(filter));
-
-  DebugResultLegacy(blocking);
+  DebugResultFormat(L"Hidden", tag, L"- " + Shorten(id), filter);
 }
 
 #endif // ENABLE_DEBUG_RESULT
@@ -243,16 +319,7 @@
 
 void CPluginDebug::DebugResultIgnoring(const std::wstring& type, const std::wstring& src, const std::wstring& domain)
 {
-  CString srcTrunc = ToCString(src);
-  if (src.length() > 100)
-  {
-    srcTrunc = srcTrunc.Left(67) + L"..." + srcTrunc.Right(30);
-  }
-
-  CString blocking;
-  blocking.Format(L"Ignored  %-12s  %s  %s", ToCString(type), domain.empty()? L"-" : ToCString(domain), srcTrunc);
-
-  DebugResultLegacy(blocking);
+  DebugResultFormat(L"Ignored", type, domain.empty() ? L"-" : domain, Shorten(src));
 }
 
 #endif // ENABLE_DEBUG_RESULT_IGNORED