Issue #1234 - Rewrite internals of debug facility

src/plugin/PluginDebug.cpp

 /*
  * This file is part of Adblock Plus <https://adblockplus.org/>,
  * Copyright (C) 2006-2015 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 "PluginMutex.h"
-#include "PluginClient.h"
+#include "PluginClientBase.h"
 #include "../shared/Utils.h"
 #include <iomanip>
+#include <memory>
 
 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;
 
   class LogText
   {
   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.

+    virtual std::string Text() const = 0;
+    virtual ~LogText() {};
   };
 
   class LogTextFixed

[sergei, 2015/12/02 13:53:00]

What about naming of classes differently?

Let's add specialization of the class for the derived extending class before the
name of the base class.
DerivedClass->Class.
For example, base class:
class Text{}; // other name examples are like "Exception", "Tool", "Filter", etc
and derived class:
class FixedText: public Text{}; // "FileNotFoundException",
"OutOfMemoryException", "LogTool", "FileTool", "BlockingFilter",
"ExceptionFilter".
Pay attention that it's clear that "FilterException" is an exception and
"ExceptionFilter" is a filter. Depending on the domain "ExceptionFilter" can be
also a part of "Exception", it still works.

And for components (parts) of the class let's add the name of the part at the
end of the class name.
Class, ClassPart.
For example,
class Exception;// consists from some parts. Another example is "Filter".
The possible components of "Exception" class can be for example,
"ExceptionMessage", "ExceptionLocation", any "ExceptionPart". For `Filter` -
'FilterRule", "FilterName", "FilterAuthor".

More complex example, compare the sounding of "ExceptionFilterType" and
"TypeFilterException".

So, according to the rules above, `LogTextFixed` should be named as
`FixedLogText`.

[Eric, 2015/12/02 15:01:24]

No.

Naming the subclasses of 'class LogText' with the prefix "LogText" means that
they all appear adjacently in documentation and class browsers, which present
names in lexicographic order. This is quite useful in situations like the
present case where there's lots of small variation on a basic theme. Ordinarily
you don't include the base class name at all and use a more descriptive name. If
you feel a need to include the base class name in a subclass name, the base name
should go at the beginning.

As for prefixing members with the class name, that's a technique required for
primitive languages without proper support for scoped names. In C++, we can say
"classname::member" or "classname.member" (depending on context) if we want
name-appending behavior.

     : 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.

+    explicit LogTextFixed(const std::string& text)
       : 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".

+    explicit LogTextFixed(const std::exception& ex)
+      : fixedText(std::string("!!! Exception: ") + ex.what())
+    {}
+
+    virtual std::string Text() const override

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

I would propose to omit `virtual` when we use `override` and always use
`override` to re-/implement any virtual method.

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

It's good to have both in place. Makes the intent crystal clear.

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

Actually, I would like to note that it's not related to this issue, we can
discuss it somewhere else, I merely wanted to attract the attention.

`virtual` was very useful until introduction of `override`, now it merely
increases the line width because `override` cannot be used for non-virtual
methods.

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

OK.

     {
       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
+    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();
     }
   };
 
-  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;

[sergei, 2015/12/02 13:53:00]

Just in case, what is the reason of extensively putting const for member types?
In this particular case only std::unique_ptr is "constant" but we are still
allowed to call non-const methods of `LogText`, although there is no any one.

[Eric, 2015/12/02 15:01:24]

'const' members mean "initialized only at construction time". I use it to get
compiler assistance to prevent accidental modification of the member. 'LogEntry'
would like to be a POD (plain old data) type, but because the data has to vary,
it can't be. There's not particularly great support for variant types in C++
(unlike, say, Ada95), so we do with polymorphism.
FYI. Apropos the present case for 'LogEntry::text', I drop the 'const'
declaration on this member in the next change set. It interfered with writing a
move constructor. Arguably this is a deficiency in C++, since 'const' means
"constant for the scope beginning after member initialization and ending at the
return of the destructor" rather than "constant for the scope beginning after
the return of the constructor and before the execution of the destructor".
There's no way of expressing the latter notion.

The 'const' declaration, though, works for the present change set. No need to
change it here.

 
-    std::string InitialPrefix()
+    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()
+    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;
 
-    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.

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

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

this method should be const

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

Done.

+    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);
           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.

+    void WriteFile(const std::wstring& logFileName) const
     {
       std::ofstream out;
       out.open(logFileName, std::ios::app);

[sergei, 2015/12/02 13:53:00]

I wonder whether we need a synchronization here. Even later with a logging
thread which  can keep the file opened all the time, how reliable does
opening/creating of the file from multiple processes work?

[Eric, 2015/12/02 15:01:24]

Easy answer: This locking behavior is the same as it was before and as it has
been for the last few years. We seem to have had no trouble with it so far.

Behavior as-used answer: This code executes immediately upon construction of the
first BHO object, since there's a log message there. There seems to be enough
time delay in construction of the second BHO object for the file operation to
complete before a possible race.

Documentation-based answer: I believe that file open/create operations are
atomic on local Windows file systems. I could be mistaken on that, though, and I
haven't dug through documentation to find out. It's conceivable that this might
fail if ABP is installed on a network drive. Message to developers: Don't do
that. In other words, if it fails, it doesn't matter if no one's looking at the
logs.

Immediate answer: Regardless of any of the above, it's out of scope at present
as another candidate synchronization change.

       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.

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

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

it also should be const

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

Done.

+  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)
 {
@@ skipping 10 matching lines @@
 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);
 }
 
 #if (defined ENABLE_DEBUG_INFO)
 
 void CPluginDebug::DebugException(const std::exception& ex)
 {
-  auto lt = new LogTextException(ex);
+  auto lt = new LogTextFixed(ex);
+  LogEntry le(lt);
 #ifdef ENABLE_DEBUG_ERROR
-  LogWriteDefault(LogEntry(lt));
+  LogWriteDefault(le);
 #endif
   DEBUG_SELFTEST(
     "********************************************************************************\n"
-    + lt.text() + "\n"
+    + lt->text() + "\n"
     "********************************************************************************")
 }
 
 void CPluginDebug::DebugErrorCode(DWORD errorCode, const std::string& error, DWORD processId, DWORD threadId)
 {
   auto lt = new LogTextErrorCode(errorCode, error);
+  LogEntry le(lt, processId, threadId);
 #ifdef ENABLE_DEBUG_ERROR
-  LogWriteDefault(LogEntry(lt, processId, threadId));
+  LogWriteDefault(le);
 #endif
   DEBUG_SELFTEST(
     "********************************************************************************\n"
-    + lt.text() + "\n"
+    + lt->text() + "\n"
     "********************************************************************************")
 }
 
 #endif
 
 // ============================================================================
 // Debug result
 // ============================================================================
 
 #ifdef ENABLE_DEBUG_RESULT
@@ skipping 49 matching lines @@
 
 
 #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