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
@@ skipping 12 matching lines @@
 #include "../shared/Utils.h"
 #include <iomanip>
 #include <memory>
 
 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.

 
   public:
     CPluginDebugLock()
       : CPluginMutex(L"DebugFile", PLUGIN_ERROR_MUTEX_DEBUG_FILE)
     {
       s_criticalSectionDebugLock.Lock();
     }
 
     ~CPluginDebugLock()
     {
       s_criticalSectionDebugLock.Unlock();
     }
   };
 
   CComAutoCriticalSection CPluginDebugLock::s_criticalSectionDebugLock;
 
   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.

   {
   public:
     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:
     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

[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;
@@ skipping 20 matching lines @@
     : 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() 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 28 matching lines @@
     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);

[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(const LogEntry& le)
@@ skipping 116 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