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
@@ -16,32 +16,225 @@
  */
 
 #include "PluginStdAfx.h"
-
 #include "PluginDebug.h"
 #include "PluginMutex.h"
-#include "PluginSettings.h"
+#include "PluginClient.h"
+#include "../shared/Utils.h"
+#include <iomanip>
 
-class CPluginDebugLock : public CPluginMutex
+namespace
 {
+  class CPluginDebugLock
+    : public CPluginMutex
+  {
+  private:
+    static CComAutoCriticalSection s_criticalSectionDebugLock;
 
-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
   {
-    s_criticalSectionDebugLock.Lock();
+  public:
+    virtual std::string text() =0;

[Oleksandr, 2015/03/19 03:46:12]

Method names should start with a capital letter. Also, a space after '=' would
be nice

[Eric, 2015/03/19 12:56:35]

I'll fix the function name.

There's an old convention that "=0" (no spaces) is the signal for a pure virtual
function declaration in C++.

[sergei, 2015/03/30 13:45:26]

This "no spaces" is not necessary, I also expect to have a space here.

[Eric, 2015/03/31 15:42:22]

Done.

+  };
+
+  class LogTextFixed
+    : public LogText
+  {
+  protected:
+    const std::string fixedText;
+
+  public:
+    LogTextFixed(std::string text)
+      : fixedText(text)
+    {}
+
+    virtual std::string text()
+    {
+      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()
+    {
+      std::ostringstream ss;
+      ss << fixedText << ". error = " << errorCode << " (0x";
+      ss << std::setfill('0') << std::setw(2 * sizeof(DWORD)) << std::hex << errorCode;
+      ss << ")";
+      return ss.str();
+    }
+  };
+
+  class LogTextException
+    : public LogText
+  {
+  protected:
+    const std::exception ex;
+
+  public:
+    LogTextException(const std::exception& ex)
+      : ex(ex)
+    {}
+
+    virtual std::string text()
+    {
+      auto text = std::string("!!! Exception: ");
+      text += ex.what();
+      return text;
+    }
+  };
+
+  /**
+   * 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()
+    {
+      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()
+    {
+      return "                     + ";

[Oleksandr, 2015/03/19 03:46:12]

NIT: Just spaces without + would look better, IMO.

[Eric, 2015/03/19 12:56:35]

This is something of an existing convention in multiple-line log message, that
there's a marker for a continuation line. We have "-" in that column already
marking the first line. I added a "+" to clearly mark that it was a subsequent
line.

Here's a sample of what it looks like: (Make sure to widen the window so it
doesn't wrap.)

14:41:24.219 [ 2476] - CPluginClass::<constructor>, this = 003a4180
14:41:24.224 [11388] -
================================================================================
                     + TAB THREAD process=1259211388
                     +
================================================================================
14:41:24.225 [ 2476] -
================================================================================
                     + NEW TAB UI
                     +
================================================================================
14:41:24.227 [ 2476] - CPluginClass::SetSite, this = 003a4180, browser =
0037b624 - Loaded as BHO
14:41:24.230 [ 8276] - InitObject

[Eric, 2015/03/20 10:17:04]

So much for that good intention. You can see the full-width version in a
wide-enough text area while editing a reply.

+    }
+
+  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;
+
+    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)
+    {
+      CPluginDebugLock lock;
+      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)
+    {
+      std::ofstream out;
+      out.open(logFileName, std::ios::app);
+      Write(out);
+    }
+  };
+
+  std::wstring GetDataPath(const std::wstring& filename)
+  {
+    return GetAppDataPath() + L"\\" + filename;
+  }
+
+  void LogWriteDefault(LogEntry& le)
+  {
+    std::wstring debugFileName = GetDataPath(L"debug_" + std::to_wstring(le.processId) + L".txt");
+    le.WriteFile(debugFileName);
   }
 
-  ~CPluginDebugLock()
+  void LogWriteResult(LogEntry& le)
   {
-    s_criticalSectionDebugLock.Unlock();
+    std::wstring debugFileName = GetDataPath(L"debug_result.txt");
+    le.WriteFile(debugFileName);
   }
-};
+}
+  
+#ifdef ENABLE_DEBUG_INFO
 
-CComAutoCriticalSection CPluginDebugLock::s_criticalSectionDebugLock;
+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)
 {
@@ -49,118 +242,30 @@
   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 LogTextException(ex);
 #ifdef ENABLE_DEBUG_ERROR
-  Debug(error);
+  LogWriteDefault(LogEntry(lt));
 #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);
+#ifdef ENABLE_DEBUG_ERROR
+  LogWriteDefault(LogEntry(lt, processId, threadId));
+#endif
+  DEBUG_SELFTEST(
+    "********************************************************************************\n"
+    + lt.text() + "\n"
+    "********************************************************************************")
 }
 
 #endif
@@ -171,69 +276,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)

[Oleksandr, 2015/03/19 03:46:12]

Kind of ambiguous name, IMO. How about DebugShortenString?

[Eric, 2015/03/19 12:56:35]

I'd worry about it if it wasn't in anonymous namespace and declared immediately
before use.

+  {
+    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 +330,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