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;

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

I guess, the method should have const modifier.

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

Done.

+  };
+
+  class LogTextFixed
+    : public LogText
+  {
+  protected:
+    const std::string fixedText;
+
+  public:
+    LogTextFixed(std::string text)

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

explicit and const ref are missed

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

We don't have 'explict' in VS 2012.

'const' done.

[sergei, 2015/04/02 07:41:12]

Why do we not have explicit in VS 2012? It's a good practice and according to
our code style it should be used for constructors with one argument if it's not
a copy constructor.

[Eric, 2015/05/19 15:13:56]

I'm confused. We don't have 'explicit' for conversion operators. We do for
constructors.
It's good practice when there's a possibility of unwanted implicit conversion
operations. There's not such possibility here.

Barring that possibility, the extra declaration is junk syntax.
Yes, that also true. I had to look it up, though.

While I still think it's junk syntax, I've added it.

+      : fixedText(text)
+    {}
+
+    virtual std::string Text() override

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

I remembered to look this up. VS 2012 does support the contextual keyword
"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() 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();
+    }
+  };
+
+  class LogTextException
+    : public LogText
+  {
+  protected:
+    const std::exception ex;
+
+  public:
+    LogTextException(const std::exception& ex)
+      : ex(ex)

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

I'm not sure that it is safe to copy std::exception because we can lose the
information if there is some DerivedException.

What about replacing LogText and derived classes by functions `std::string
FormatToDebugString(const std::exception& ex)` and `std::string
FormatToDebugString(DWORD errorCode, const std::string& text)` and make LogEntry
constructor to accept `const std::string&` instead of LogText*?

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

The point behind subclassing LogText is to defer calculation of the log string
until it's time to write to the log. In general, the thread that the class is
instantiated in won't be the same as writes to the log. See my initial comment
#1 above for more.
    http://codereview.adblockplus.org/5187613258416128/#msg1

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

You're right; it's not. There's also no 'clone()' member of 'std::exception'.

I've eliminated the class and added another constructor to 'LogTextFixed'. It
evaluates 'what()' in the constructor, which I don't like, but it will be
adequate for now. The alternative is to use 'make_exception_ptr' and
'rethrow_exception', which is overkill for what we need at this point. If we
ever need very high performance for queuing a log entry, such as for a DLL entry
point, we can implement it then.

[sergei, 2015/04/02 07:41:12]

It's clear, but I would say lazy evaluation here makes insignificant
contribution. However, I think it could be useful to have LogEntry structure
(without inheritance) where we can also store the function name, file name, line
number, thread ID and other useful information of the log caller.

[Eric, 2015/05/19 15:13:56]

I'll leave it in. It's not harming anything. I may need it later and I don't
want an extensive rewrite in the present change set.
Perhaps this should all go in the 'LogEntry' class, perhaps not. There's some
more rewriting of the debug facilities to do first. When that all falls out, it
may be clearer.

One thing that is clear to me, though, is that we can get something stack traces
by using our own exception classes with function/file/line information and using
nested exceptions. In that case the top level exception provides information we
don't need duplicated in the log. Other kinds of log messages, though, would
still need them. The upshot is that I'm going to finish the debug facility
generally before I consider those next steps.

+    {}
+
+    virtual std::string Text() override
+    {
+      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 "                     + ";
+    }
+
+  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)

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

explicit is missed

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

No 'explicit' in VS 2012.

+      : processId(::GetCurrentProcessId()), threadId(::GetCurrentThreadId()), text(text)
+    {}
+
+    LogEntry(LogText* text, DWORD processId, DWORD threadId)
+      : processId(processId), threadId(threadId), text(text)
+    {}
+
+    void Write(std::ostream& out)

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

this method should be const

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

Done.

+    {
+      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)

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

it also should be const

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

Done.

+    {
+      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)

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

LogEntry should be const ref

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

Done.

+  {
+    std::wstring debugFileName = GetDataPath(L"debug_" + std::to_wstring(le.processId) + L".txt");
+    le.WriteFile(debugFileName);
   }
 
-  ~CPluginDebugLock()
+  void LogWriteResult(LogEntry& le)

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

it also should be const

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

Done.

   {
-    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)
+  {
+    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