Added default and verbose logging for all core and shellextension cla…

…sses #109

src/core/ActionManager.cpp

@@ -33,13 +33,15 @@ namespace shellanything
 
   bool ActionManager::Execute(const Menu* menu, const SelectionContext& context)
   {
+    shellanything::ScopeLogger verbose_scope_logger(__FUNCTION__ "()", true);
+
     //compute the visual menu title
     shellanything::PropertyManager& pmgr = shellanything::PropertyManager::GetInstance();
     std::string title = pmgr.Expand(menu->GetName());
 
     bool success = true;
 
-    SA_LOG(INFO) << "Executing action(s) for menu '" << title.c_str() << "'...";
+    SA_LOG(INFO) << "Executing action(s) for menu '" << title.c_str() << "', id=" << menu->GetCommandId() << "...";
 
     //execute actions
     const shellanything::IAction::ActionPtrList& actions = menu->GetActions();
@@ -59,7 +61,7 @@ namespace shellanything
           if (dwError)
           {
             std::string error_message = ra::errors::GetErrorCodeDescription(dwError);
-            SA_LOG(ERROR) << "Action #" << (i + 1) << " has failed: " << error_message;
+            SA_LOG(ERROR) << "Action #" << (i + 1) << " has failed: " << LoggerHelper::ToHex(dwError) << ", " << error_message;
           }
           else
           {

src/core/ActionOpen.cpp

@@ -139,14 +139,19 @@ namespace shellanything
     {
       SA_LOG(INFO) << "Open file '" << path << "'.";
       uint32_t pId = ra::process::OpenDocumentUtf8(path);
-      return pId != ra::process::INVALID_PROCESS_ID;
+      bool success = (pId != ra::process::INVALID_PROCESS_ID);
+      if (!success)
+        SA_LOG(ERROR) << "Failed opening file '" << path << "'.";
+      return success;
     }
 
     //is path a directory?
     if (ra::filesystem::DirectoryExistsUtf8(path.c_str()))
     {
       SA_LOG(INFO) << "Open directory '" << path << "'.";
       bool success = OpenPathGeneric(path);
+      if (!success)
+        SA_LOG(ERROR) << "Failed opening directory '" << path << "'.";
       return success;
     }
 
@@ -156,6 +161,8 @@ namespace shellanything
     {
       SA_LOG(INFO) << "Open url '" << path << "'.";
       bool success = OpenPathGeneric(path);
+      if (!success)
+        SA_LOG(ERROR) << "Failed opening URL '" << path << "'.";
       return success;
     }
 

src/core/ActionProperty.cpp

@@ -259,7 +259,7 @@ namespace shellanything
       }
     }
 
-    // If regisrykey is specified, it has priority over value. This is required to allow setting a property to an empty value (a.k.a. value="").
+    // If registrykey is specified, it has priority over value. This is required to allow setting a property to an empty value (a.k.a. value="").
     if (!registrykey.empty())
     {
       std::string tmp_value;

src/core/ActionStop.cpp

@@ -115,7 +115,7 @@ namespace shellanything
 
     bool validated = mValidator->Validate(context);
 
-    //update the property
+    //log the result
     if (validated)
       SA_LOG(INFO) << "ActionStop: Validation is successful.";
     else

src/core/ConfigFile.cpp

@@ -119,6 +119,10 @@ namespace shellanything
 
   ConfigFile* ConfigFile::LoadFile(const std::string& path, std::string& error)
   {
+    ScopeLogger verbose_scope_logger(__FUNCTION__ "()", true);
+
+    SA_VERBOSE_LOG(INFO) << "Loading configuration file '" << path << "'.";
+
     error = "";
 
     if (!ra::filesystem::FileExistsUtf8(path.c_str()))
@@ -339,17 +343,21 @@ namespace shellanything
 
   void ConfigFile::Update(const SelectionContext& context)
   {
+    ScopeLogger verbose_scope_logger(__FUNCTION__ "()", this, true);
+
     SetUpdatingConfigFile(this);
 
     //run callbacks of each plugins
     //for each plugins
     for (size_t i = 0; i < mPlugins.size(); i++)
     {
       Plugin* p = mPlugins[i];
+      SA_VERBOSE_LOG(INFO) << "Running update callbacks of plugin '" << p->GetPath() << "'.";
       Registry& registry = p->GetRegistry();
       size_t count = registry.GetUpdateCallbackCount();
       for (size_t j = 0; j < count; j++)
       {
+        SA_VERBOSE_LOG(INFO) << "Executing update callback " << (j + 1) << " of " << count << ".";
         IUpdateCallback* callback = registry.GetUpdateCallbackFromIndex(j);
         callback->SetSelectionContext(&context);
         callback->OnNewSelection();
@@ -372,8 +380,10 @@ namespace shellanything
   {
     if (mDefaults && mDefaults->GetActions().size() > 0)
     {
+      ScopeLogger verbose_scope_logger(__FUNCTION__ "()", this, true);
+
       //configuration have default properties assigned
-      SA_LOG(INFO) << __FUNCTION__ << "(), initializing default properties of configuration file '" << mFilePath.c_str() << "'...";
+      SA_LOG(INFO) << "Initializing default properties of configuration file '" << mFilePath.c_str() << "'...";
 
       const shellanything::IAction::ActionPtrList& actions = mDefaults->GetActions();
 
@@ -386,13 +396,17 @@ namespace shellanything
         const shellanything::ActionProperty* action_property = dynamic_cast<const shellanything::ActionProperty*>(abstract_action);
         if (action_property)
           properties.push_back(action_property);
+        else
+        {
+          SA_LOG(WARNING) << "Action " << (i + 1) << " of " << actions.size() << " is not a <property> action!";
+        }
       }
 
       //apply all ActionProperty
       SelectionContext empty_context;
       for (size_t i = 0; i < properties.size(); i++)
       {
-        SA_LOG(INFO) << __FUNCTION__ << "(), executing property " << (i + 1) << " of " << properties.size() << ".";
+        SA_LOG(INFO) << "Executing action " << (i + 1) << " of " << properties.size() << ".";
         const shellanything::ActionProperty* action_property = properties[i];
         if (action_property)
         {
@@ -401,7 +415,7 @@ namespace shellanything
         }
       }
 
-      SA_LOG(INFO) << __FUNCTION__ << "(), execution of default properties of configuration file '" << mFilePath.c_str() << "' completed.";
+      SA_LOG(INFO) << "Execution of default properties of configuration file '" << mFilePath.c_str() << "' completed.";
     }
   }
 

src/core/ConfigManager.cpp

@@ -49,14 +49,15 @@ namespace shellanything
 
   void ConfigManager::Clear()
   {
+    SA_LOG(INFO) << __FUNCTION__ << "()";
     ClearSearchPath(); //remove all search path to make sure that a refresh won’t find any other configuration file
     DeleteChildren();
     Refresh(); //forces all loaded configurations to be unloaded
   }
 
   void ConfigManager::Refresh()
   {
-    SA_LOG(INFO) << __FUNCTION__ << "()";
+    ScopeLogger verbose_scope_logger(__FUNCTION__ "()", this, true);
 
     //validate existing configurations
     ConfigFile::ConfigFilePtrList existing = GetConfigFiles();
@@ -139,6 +140,8 @@ namespace shellanything
 
   void ConfigManager::Update(const SelectionContext& context)
   {
+    ScopeLogger verbose_scope_logger(__FUNCTION__ "()", this, true);
+
     //for each child
     ConfigFile::ConfigFilePtrList configurations = ConfigManager::GetConfigFiles();
     for (size_t i = 0; i < configurations.size(); i++)

src/core/LoggerHelper.cpp

@@ -28,8 +28,11 @@
 #include "Validator.h"
 #include <string>
 
+#include "rapidassist/strings.h"
+
 namespace shellanything
 {
+
   LoggerHelper::LoggerHelper(ILoggerService::LOG_LEVEL level) :
     mFilename(NULL),
     mLine(0),
@@ -102,25 +105,123 @@ namespace shellanything
     Environment& env = Environment::GetInstance();
 
     // Check environment variable options first.
-    if (env.IsOptionSet(Environment::SYSTEM_LOGGING_VERBOSE_ENVIRONMENT_VARIABLE_NAME))
+    static const std::string& VERBOSE_ENV_VAR_NAME = Environment::SYSTEM_LOGGING_VERBOSE_ENVIRONMENT_VARIABLE_NAME;
+    if (env.IsOptionSet(VERBOSE_ENV_VAR_NAME))
     {
-      if (env.IsOptionTrue(Environment::SYSTEM_LOGGING_VERBOSE_ENVIRONMENT_VARIABLE_NAME))
-      {
+      if (env.IsOptionTrue(VERBOSE_ENV_VAR_NAME))
         return true;
-      }
+      return false;
     }
 
     // Check internal property system.
-    if (!pmgr.HasProperty(PropertyManager::SYSTEM_LOGGING_VERBOSE_PROPERTY_NAME))
+    static const std::string& VERBOSE_PROPERTY_NAME = PropertyManager::SYSTEM_LOGGING_VERBOSE_PROPERTY_NAME;
+    if (!pmgr.HasProperty(VERBOSE_PROPERTY_NAME))
       return false; // no verbose logging
 
-    const std::string& value = pmgr.GetProperty(PropertyManager::SYSTEM_LOGGING_VERBOSE_PROPERTY_NAME);
+    const std::string& value = pmgr.GetProperty(VERBOSE_PROPERTY_NAME);
     if (value.empty())
       return false; // no verbose logging
 
     bool has_vebose_logging = Validator::IsTrue(value);
     return has_vebose_logging;
   }
 
+  void LoggerHelper::ToHex(const void* ptr, char* buffer, size_t buffer_size)
+  {
+    sprintf_s(buffer, buffer_size, "0x%p", ptr);
+  }
+
+  std::string LoggerHelper::ToHex(const void* ptr)
+  {
+    char buffer[32];
+    ToHex(ptr, buffer, sizeof(buffer));
+    return buffer;
+  }
+
+  std::string LoggerHelper::ToHex(const uint32_t value)
+  {
+    std::string s = ra::strings::Format("0x%x", value);
+    return s;
+  }
+
+  // ------------------------------------------------------------------------------------------------------------------------------------------------------------
+  // ------------------------------------------------------------------------------------------------------------------------------------------------------------
+
+  //ScopeLogger::ScopeLogger(const char* name)
+  //{
+  //  Reset();
+  //  mName = name;
+
+  //  Enter();
+  //}
+
+  ScopeLogger::ScopeLogger(const char* name, bool is_verbose, ILoggerService::LOG_LEVEL level)
+  {
+    Reset();
+    mLevel = level;
+    mName = name;
+    mIsVerbose = is_verbose;
+
+    Enter();
+  }
+
+  //ScopeLogger::ScopeLogger(const char* name, const void* calling_instance)
+  //{
+  //  Reset();
+  //  mName = name;
+  //  mCallingInstance = calling_instance;
+
+  //  Enter();
+  //}
+
+  ScopeLogger::ScopeLogger(const char* name, const void* calling_instance, bool is_verbose, ILoggerService::LOG_LEVEL level)
+  {
+    Reset();
+    mLevel = level;
+    mName = name;
+    mIsVerbose = is_verbose;
+    mCallingInstance = calling_instance;
+
+    Enter();
+  }
+
+  ScopeLogger::~ScopeLogger()
+  {
+    Leave();
+  }
+
+  void ScopeLogger::Reset()
+  {
+    mLevel = ILoggerService::LOG_LEVEL::LOG_LEVEL_INFO;
+    //mName
+    mIsVerbose = false;
+    mCallingInstance = NULL;
+  }
+
+  void ScopeLogger::Enter()
+  {
+    if (!mCallingInstance)
+      ::shellanything::LoggerHelper(mLevel, mIsVerbose) << mName << " - enter";
+    else
+    {
+      char hex_ptr_value[32];
+      LoggerHelper::ToHex(mCallingInstance, hex_ptr_value, sizeof(hex_ptr_value));
+
+      ::shellanything::LoggerHelper(mLevel, mIsVerbose) << mName << " for instance " << hex_ptr_value << "- enter";
+    }
+  }
+
+  void ScopeLogger::Leave()
+  {
+    if (!mCallingInstance)
+      ::shellanything::LoggerHelper(mLevel, mIsVerbose) << mName << " - leave";
+    else
+    {
+      char hex_ptr_value[32];
+      LoggerHelper::ToHex(mCallingInstance, hex_ptr_value, sizeof(hex_ptr_value));
+
+      ::shellanything::LoggerHelper(mLevel, mIsVerbose) << mName << " for instance " << hex_ptr_value << "- leave";
+    }
+  }
 
 } //namespace shellanything

src/core/LoggerHelper.h

@@ -66,6 +66,28 @@ namespace shellanything
     /// <returns>Returns true when verbose logging is enabled. Returns false otherwise.</returns>
     static bool IsVerboseLoggingEnabled();
 
+    /// <summary>
+    /// Converts a pointer to a hex string format. The value is prefixed with `0x`.
+    /// </summary>
+    /// <param name="ptr">The pointer value to convert.</param>
+    /// <param name="buffer">The target output buffer.</param>
+    /// <param name="buffer_size">The size in byte of the output buffer.</param>
+    static void ToHex(const void* ptr, char* buffer, size_t buffer_size);
+
+    /// <summary>
+    /// Converts a pointer to a hex string format. The value is prefixed with `0x`.
+    /// </summary>
+    /// <param name="ptr">The pointer value to convert.</param>
+    /// <returns>Returns a representation of the given pointer in hex string format.</returns>
+    static std::string ToHex(const void* ptr);
+
+    /// <summary>
+    /// Converts a numeric value to a hex string format. The value is prefixed with `0x`.
+    /// </summary>
+    /// <param name="ptr">The pointer value to convert.</param>
+    /// <returns>Returns a representation of the given pointer in hex string format.</returns>
+    static std::string ToHex(const uint32_t value);
+
   private:
     ILoggerService::LOG_LEVEL mLevel;
     bool mIsVerboseStream;
@@ -74,6 +96,48 @@ namespace shellanything
     std::stringstream mSS;
   };
 
+  /// <summary>
+  /// Helper class for logging the scope of a function or block of code.
+  /// </summary>
+  /// <example>
+  /// <code>
+  /// // For static functions:
+  /// ScopeLogger scope_logger(__FUNCTION__ "()");
+  /// ScopeLogger verbose_scope_logger(__FUNCTION__ "()", true);
+  /// ScopeLogger info_verbose_scope_logger(__FUNCTION__ "()", true, ILoggerService::LOG_LEVEL::LOG_LEVEL_INFO);
+  ///
+  /// // For class methods:
+  /// ScopeLogger scope_logger(__FUNCTION__ "()", this);
+  /// ScopeLogger verbose_scope_logger(__FUNCTION__ "()", this, true);
+  /// ScopeLogger info_verbose_scope_logger(__FUNCTION__ "()", this, true, ILoggerService::LOG_LEVEL::LOG_LEVEL_INFO);
+  /// </code>
+  /// </example>
+  class SHELLANYTHING_EXPORT ScopeLogger
+  {
+  public:
+    //ScopeLogger(const char* name);
+    ScopeLogger(const char* name, bool is_verbose = false, ILoggerService::LOG_LEVEL level = ILoggerService::LOG_LEVEL::LOG_LEVEL_DEBUG);
+    //ScopeLogger(const char* name, const void * calling_instance);
+    ScopeLogger(const char* name, const void * calling_instance, bool is_verbose = false, ILoggerService::LOG_LEVEL level = ILoggerService::LOG_LEVEL::LOG_LEVEL_DEBUG);
+    ~ScopeLogger();
+
+  private:
+    // Disable copy constructor and copy operator
+    ScopeLogger(const ScopeLogger&);
+    ScopeLogger& operator=(const ScopeLogger&);
+
+  private:
+    void Reset();
+    void Enter();
+    void Leave();
+
+  public:
+    ILoggerService::LOG_LEVEL mLevel;
+    std::string mName;
+    bool mIsVerbose;
+    const void* mCallingInstance;
+  };
+
   #ifndef SA_LOG
   #define SA_LOG(expr)          (::shellanything::LoggerHelper(__FILE__, __LINE__, ::shellanything::ILoggerService::LOG_LEVEL_##expr, false))
   #endif