--[BE Week] Minimize logging spam (#2140)

* --change default level to warning instead of debug
* --demote inappropriate warning messages to debug level.
* --fix test
* --address faulty error message when attempting to get default light setup.
* --make scene instance load messages more lucid and at appropriate level
* --add message level/type to message
In decreasing severity order : 'Error', 'Warning', 'Debug', 'Verbose'
* --"Message" -> "Verbose"

Author: jturner65

src/esp/core/Logging.cpp

@@ -55,6 +55,7 @@ LoggingLevel levelFromName(const Corrade::Containers::StringView name) {
   CASE(VeryVerbose, veryverbose);
   CASE(Verbose, verbose);
   CASE(Debug, debug);
+  CASE(Default, default);
   CASE(Warning, warning);
   CASE(Quiet, quiet);
   CASE(Error, error);
@@ -137,6 +138,7 @@ bool isLevelEnabled(Subsystem subsystem, LoggingLevel level) {
 }
 
 Cr::Containers::String buildMessagePrefix(Subsystem subsystem,
+                                          const std::string& msgLevel,
                                           const std::string& filename,
                                           const std::string& function,
                                           int line) {
@@ -154,9 +156,10 @@ Cr::Containers::String buildMessagePrefix(Subsystem subsystem,
   std::tm timeNow = *std::localtime(&t);
 
   return Cr::Utility::formatString(
-      "[{:.02d}:{:.02d}:{:.02d}:{:.06d}]:[{}] {}({})::{} : ", timeNow.tm_hour,
-      timeNow.tm_min, timeNow.tm_sec, nowMicros.count(),
-      subsystemNames[uint8_t(subsystem)], baseFileName, line, function);
+      "[{:.02d}:{:.02d}:{:.02d}:{:.06d}]:[{}]:[{}] {}({})::{} : ",
+      timeNow.tm_hour, timeNow.tm_min, timeNow.tm_sec, nowMicros.count(),
+      msgLevel, subsystemNames[uint8_t(subsystem)], baseFileName, line,
+      function);
 }
 
 }  // namespace logging

src/esp/core/Logging.h

@@ -122,27 +122,43 @@ namespace logging {
  * greater than or equal to the logging level within that subsystem, the log
  * will be printed.
  *
- * The convience levels, @ref Verbose and @ref Quiet are the primary user facing
- * options.  @ref Quiet turns off logging and @ref Verbose is the default and
- * shows things that are generally useful.  These names exist such that logging
- * levels can be added and removed without users needed to change what they set
- * logging to.
+ * The convenience levels, @ref Verbose, @ref Default and @ref Quiet are the primary user facing
+ * options.  @ref Quiet turns off logging for all but errors, @ref Default is the default and
+ * shows warnings and errors, while @ref Verbose gives debug messages along with warnings and
+ * errors. These names exist such that logging levels can be added and removed
+ * without users needing to change what they set logging to.
  */
 enum class LoggingLevel : uint8_t {
+  /**
+   * Logging level to be used to provide in depth information about a process
+   * and its result.
+   */
   VeryVerbose,
+
+  /**
+   * Logging level to be used to specify the result of some process.
+   */
   Debug,
+  /**
+   * Logging level to be used to denote that some process has yielded a result
+   * that may not be appropriate or expected.
+   */
   Warning,
+  /**
+   * Logging level to be used to denote that some process has failed.
+   */
   Error,
 
   /**
-   * The default logging level.  Enables all logging except for the most verbose
-   * statements. Habitat-Sim will be fairly verbose in this setting, but not
-   * overly so.
-   *
-   * Note: If you add another level that is lower priority than Debug but should
-   * be on by default or Debug is removed/renamed, this will need to be updated.
+   * Enables all logging except for the most verbose statements. Habitat-Sim
+   * will be fairly verbose in this setting, but not overly so.
    */
   Verbose = Debug,
+  /**
+   * The default logging level. Enables all warning and error messages but hides
+   * debug and verbose messages.
+   */
+  Default = Warning,
   /**
    * Turns of all non-critical logging messages, i.e. those that indicate that
    * something has gone wrong.
@@ -165,7 +181,7 @@ LoggingLevel levelFromName(Corrade::Containers::StringView name);
 class LoggingContext {
  public:
   constexpr static const char* LOGGING_ENV_VAR_NAME = "HABITAT_SIM_LOG";
-  constexpr static LoggingLevel DEFAULT_LEVEL = LoggingLevel::Verbose;
+  constexpr static LoggingLevel DEFAULT_LEVEL = LoggingLevel::Default;
 
   /**
    * @brief Convenience constructor that grabs the configuration string from the
@@ -246,6 +262,7 @@ bool isLevelEnabled(Subsystem subsystem, LoggingLevel level);
  * subsystem/namespace, file, line number and function name
  */
 Corrade::Containers::String buildMessagePrefix(Subsystem subsystem,
+                                               const std::string& msgLevel,
                                                const std::string& filename,
                                                const std::string& function,
                                                int line);
@@ -304,10 +321,10 @@ class LogMessageVoidify {
 
 // This ends with a nospace since the space is baked in to subsystemPrefix for
 // the case that the logger was created with a nospace flag.
-#define ESP_SUBSYS_LOG_IF(subsystem, level, output)                        \
-  ESP_LOG_IF(esp::logging::isLevelEnabled((subsystem), (level)), (output)) \
-      << esp::logging::buildMessagePrefix((subsystem), (__FILE__),         \
-                                          (__FUNCTION__), (__LINE__))      \
+#define ESP_SUBSYS_LOG_IF(subsystem, level, output, levelMsg)                  \
+  ESP_LOG_IF(esp::logging::isLevelEnabled((subsystem), (level)), (output))     \
+      << esp::logging::buildMessagePrefix((subsystem), (levelMsg), (__FILE__), \
+                                          (__FUNCTION__), (__LINE__))          \
       << Corrade::Utility::Debug::nospace
 
 #define ESP_LOG_LEVEL_ENABLED(level) \
@@ -320,25 +337,26 @@ class LogMessageVoidify {
   ESP_SUBSYS_LOG_IF(                                                     \
       espLoggingSubsystem(), esp::logging::LoggingLevel::VeryVerbose,    \
       (Corrade::Utility::Debug{Corrade::Utility::Debug::defaultOutput(), \
-                               __VA_ARGS__}))
+                               __VA_ARGS__}),                            \
+      "Verbose")
 /**
  * @brief Debug level logging macro.
  */
 #define ESP_DEBUG(...)                                                        \
   ESP_SUBSYS_LOG_IF(espLoggingSubsystem(), esp::logging::LoggingLevel::Debug, \
-                    Corrade::Utility::Debug{__VA_ARGS__})
+                    Corrade::Utility::Debug{__VA_ARGS__}, "Debug")
 /**
  * @brief Warning level logging macro.
  */
 #define ESP_WARNING(...)                                 \
   ESP_SUBSYS_LOG_IF(espLoggingSubsystem(),               \
                     esp::logging::LoggingLevel::Warning, \
-                    Corrade::Utility::Warning{__VA_ARGS__})
+                    Corrade::Utility::Warning{__VA_ARGS__}, "Warning")
 /**
  * @brief Error level logging macro.
  */
 #define ESP_ERROR(...)                                                        \
   ESP_SUBSYS_LOG_IF(espLoggingSubsystem(), esp::logging::LoggingLevel::Error, \
-                    Corrade::Utility::Error{__VA_ARGS__})
+                    Corrade::Utility::Error{__VA_ARGS__}, "Error")
 
 #endif  // ESP_CORE_LOGGING_H_

src/esp/metadata/MetadataMediator.cpp

@@ -328,7 +328,7 @@ MetadataMediator::makeSceneAndReferenceStage(
   ESP_CHECK(datasetAttr != nullptr && stageAttributes != nullptr &&
                 dsSceneAttrMgr != nullptr,
             "Missing (at least) one of scene dataset attributes, stage "
-            "attributes, or dataset scene attributes for scene '"
+            "attributes, or scene instance attributes for scene '"
                 << Mn::Debug::nospace << sceneName << Mn::Debug::nospace
                 << "'.  Likely an invalid scene name.");
   // create scene attributes with passed name

src/esp/metadata/attributes/SceneDatasetAttributes.cpp

@@ -74,7 +74,7 @@ bool SceneDatasetAttributes::addNewSceneInstanceToDataset(
   // should only be empty if not specified in scene instance config, or if scene
   // instance config is synthesized (i.e. when Simulator::reconfigure is called
   // with SimulatorConfiguration::activeSceneName being a stage)
-  if (lightHandle.length() == 0) {
+  if (lightHandle.empty()) {
     lightHandle = sceneInstanceName;
   }
 
@@ -132,16 +132,15 @@ std::pair<std::string, std::string> SceneDatasetAttributes::addNewValToMap(
         } while (map.count(newKey) > 0);
         ESP_WARNING(Mn::Debug::Flag::NoSpace)
             << descString << " : Provided key '" << key
-
-            << "' already references a different value in "
-               "map. Modifying key to be"
+            << "' already references a different value in map. Modifying key "
+               "to be '"
             << newKey
-            << ". Set overwrite to true to overwrite existing entries.";
+            << "'. Set overwrite to true to overwrite existing entries.";
       } else {  // overwrite entry
-        ESP_WARNING() << descString
-                      << ": Warning : Overwriting existing map entry"
-                      << map.at(newKey) << "at key" << newKey << "with value"
-                      << path << ".";
+        ESP_WARNING(Mn::Debug::Flag::NoSpace)
+            << descString << " : Overwriting existing map entry "
+            << map.at(newKey) << " at key '" << newKey << "' with value'"
+            << path << "'.";
       }  // overwrite or not
     }    // found entry is desired or not
   }      // key is found

src/esp/metadata/managers/AbstractObjectAttributesManagerBase.h

@@ -174,15 +174,18 @@ auto AbstractObjectAttributesManager<T, Access>::createObject(
     // this is a primitive-based object we are building
     attrs = this->createPrimBasedAttributesTemplate(attributesTemplateHandle,
                                                     registerTemplate);
-    msg = "Primitive Asset (" + attributesTemplateHandle + ") Based";
+    if (ESP_LOG_LEVEL_ENABLED(logging::LoggingLevel::Debug)) {
+      msg = "Primitive Asset (" + attributesTemplateHandle + ") Based";
+    }
   } else {
     attrs = this->createFromJsonOrDefaultInternal(attributesTemplateHandle, msg,
                                                   registerTemplate);
 
   }  // if this is prim else
   if (nullptr != attrs) {
-    ESP_DEBUG() << msg << this->objectType_ << "attributes created"
-                << (registerTemplate ? "and registered." : ".");
+    ESP_DEBUG(Mn::Debug::Flag::NoSpace)
+        << msg << " " << this->objectType_ << " attributes created"
+        << (registerTemplate ? " and registered." : ".");
   }
   return attrs;
 

src/esp/metadata/managers/AssetAttributesManager.cpp

@@ -110,7 +110,7 @@ AssetAttributesManager::AssetAttributesManager()
   }
 
   ESP_DEBUG() << "Built default primitive asset templates :"
-              << std::to_string(defaultPrimAttributeHandles_.size());
+              << defaultPrimAttributeHandles_.size();
 }  // AssetAttributesManager::ctor
 
 AbstractPrimitiveAttributes::ptr AssetAttributesManager::createObject(
@@ -137,16 +137,18 @@ AssetAttributesManager::createTemplateFromHandle(
   std::size_t nameEndLoc = templateHandle.find('_');
   if (nameEndLoc == std::string::npos) {
     // handle is of incorrect format
-    ESP_ERROR() << "Given template handle :" << templateHandle
-                << "is not the correct format for a primitive.  Aborting.";
+    ESP_ERROR(Mn::Debug::Flag::NoSpace)
+        << "Given template handle : `" << templateHandle
+        << "` is not the correct format for a primitive.  Aborting.";
     return nullptr;
   }
   std::string primClassName = templateHandle.substr(0, nameEndLoc);
   if (primTypeConstructorMap_.count(primClassName) == 0) {
     // handle does not have proper primitive tyep encoded
-    ESP_ERROR() << "Requested primitive type :" << primClassName
-                << "from given template handle :" << templateHandle
-                << "is not a valid Magnum::Primitives class.  Aborting.";
+    ESP_ERROR(Mn::Debug::Flag::NoSpace)
+        << "Requested primitive type : `" << primClassName
+        << "` from given template handle : `" << templateHandle
+        << "` is not a valid Magnum::Primitives class.  Aborting.";
     return nullptr;
   }
   // create but do not register template for this prim class, since it will be
@@ -156,12 +158,13 @@ AssetAttributesManager::createTemplateFromHandle(
   if (templateHandle.length() > 0) {
     bool success = primAssetAttributes->parseStringIntoConfig(templateHandle);
     if (!success) {
-      ESP_WARNING() << "Prim Asset Attributes :" << primClassName
-                    << "failed parsing config string : `" << templateHandle
-                    << "`.  Providing" << primClassName
-                    << "template configured as closely as possible with "
-                       "requested values, named"
-                    << primAssetAttributes->getHandle() << ".";
+      ESP_WARNING(Mn::Debug::Flag::NoSpace)
+          << "Prim Asset Attributes : `" << primClassName
+          << "` failed parsing config string : `" << templateHandle
+          << "`. Providing `" << primClassName
+          << "` template configured as closely as possible with requested "
+             "values, named `"
+          << primAssetAttributes->getHandle() << "`.";
     }
   }
   return this->postCreateRegister(std::move(primAssetAttributes),
@@ -175,11 +178,10 @@ int AssetAttributesManager::registerObjectFinalize(
   std::string primAttributesHandle = primAttributesTemplate->getHandle();
   // verify that attributes has been edited in a legal manner
   if (!primAttributesTemplate->isValidTemplate()) {
-    ESP_ERROR() << "Primitive asset attributes template named"
-                << primAttributesHandle
-                << "is not configured properly for specified prmitive"
-                << primAttributesTemplate->getPrimObjClassName()
-                << ". Aborting.";
+    ESP_ERROR(Mn::Debug::Flag::NoSpace)
+        << "Primitive asset attributes template named `" << primAttributesHandle
+        << "` is not configured properly for specified prmitive `"
+        << primAttributesTemplate->getPrimObjClassName() << "`. Aborting.";
     return ID_UNDEFINED;
   }
 
@@ -204,19 +206,21 @@ AbstractPrimitiveAttributes::ptr AssetAttributesManager::buildObjectFromJSONDoc(
   // if not legal primitive asset attributes file name, have message and
   // return default sphere attributes.
   if (defaultPrimAttributeHandles_.count(primClassName) == 0) {
-    ESP_ERROR() << "Unknown primitive class type :" << primClassName
-                << "so returning default attributes for solid uvSphere.";
+    ESP_ERROR(Mn::Debug::Flag::NoSpace)
+        << "Unknown primitive class type : `" << primClassName
+        << "` so returning default attributes for solid uvSphere.";
     return this->getObjectCopyByHandle<attributes::UVSpherePrimitiveAttributes>(
         defaultPrimAttributeHandles_.at("uvSphereSolid"));
   }
 
   // create attributes for the primitive described in the JSON file
   auto primAssetAttributes = this->initNewObjectInternal(primClassName, true);
   if (nullptr == primAssetAttributes) {
-    ESP_ERROR() << "Unable to create default primitive asset attributes from "
-                   "primClassName"
-                << primClassName
-                << "so returning default attributes for solid uvSphere.";
+    ESP_ERROR(Mn::Debug::Flag::NoSpace)
+        << "Unable to create default primitive asset attributes from "
+           "primClassName `"
+        << primClassName
+        << "` so returning default attributes for solid uvSphere.";
     return this->getObjectCopyByHandle<attributes::UVSpherePrimitiveAttributes>(
         defaultPrimAttributeHandles_.at("uvSphereSolid"));
   }

src/esp/metadata/managers/AttributesManagerBase.h

@@ -339,8 +339,9 @@ void AttributesManager<T, Access>::buildAttrSrcPathsFromJSONAndLoad(
     const io::JsonGenericValue& filePaths) {
   for (rapidjson::SizeType i = 0; i < filePaths.Size(); ++i) {
     if (!filePaths[i].IsString()) {
-      ESP_ERROR() << "Invalid path value in file path array element @ idx" << i
-                  << ". Skipping.";
+      ESP_ERROR() << "<" << this->objectType_
+                  << "> : Invalid path value in file path array element @ idx"
+                  << i << ". Skipping.";
       continue;
     }
     std::string absolutePath =
@@ -349,12 +350,14 @@ void AttributesManager<T, Access>::buildAttrSrcPathsFromJSONAndLoad(
     if (globPaths.size() > 0) {
       for (const auto& globPath : globPaths) {
         // load all object templates available as configs in absolutePath
-        ESP_WARNING() << "Glob path result for" << absolutePath << ":"
-                      << globPath;
+        ESP_DEBUG() << "<" << this->objectType_ << "> : Glob path result for"
+                    << absolutePath << ":" << globPath;
         this->loadAllTemplatesFromPathAndExt(globPath, extType, true);
       }
     } else {
-      ESP_WARNING() << "No Glob path result for" << absolutePath;
+      ESP_WARNING(Mn::Debug::Flag::NoSpace)
+          << "<" << this->objectType_ << "> : No Glob path result for "
+          << absolutePath << " so unable to load templates.";
     }
   }
   ESP_DEBUG(Mn::Debug::Flag::NoSpace)
@@ -385,7 +388,9 @@ auto AttributesManager<T, Access>::createFromJsonOrDefaultInternal(
   if (jsonFileExists) {
     // configuration file exists with requested name, use to build Attributes
     attrs = this->createObjectFromJSONFile(jsonAttrFileName, registerObj);
-    msg = "JSON Configuration File (" + jsonAttrFileName + ") based";
+    if (ESP_LOG_LEVEL_ENABLED(logging::LoggingLevel::Debug)) {
+      msg = "JSON Configuration File (" + jsonAttrFileName + ") based";
+    }
   } else {
     // An existing, valid configuration file could not be found using the
     // passed filename. Currently non-JSON filenames are used to create new,
@@ -395,12 +400,15 @@ auto AttributesManager<T, Access>::createFromJsonOrDefaultInternal(
     bool fileExists = Cr::Utility::Path::exists(filename);
     // if filename passed is name of some kind of asset, or if it was not
     // found
-    if (fileExists) {
-      msg = "File (" + filename +
-            ") exists but is not a recognized config filename extension, so "
-            "new default";
-    } else {
-      msg = "File (" + filename + ") not found, so new default";
+    if (ESP_LOG_LEVEL_ENABLED(logging::LoggingLevel::Debug)) {
+      // only populate msg if appropriate logging level is enabled
+      if (fileExists) {
+        msg = "File (" + filename +
+              ") exists but is not a recognized config filename extension, so "
+              "new default";
+      } else {
+        msg = "File (" + filename + ") not found, so new default";
+      }
     }
   }
   return attrs;