[Logging] Expand logging output information

src/esp/core/logging.cpp

@@ -11,6 +11,7 @@
 #include <Corrade/Containers/Array.h>
 #include <Corrade/Containers/StaticArray.h>
 #include <Corrade/Containers/String.h>
+#include <Corrade/Utility/Directory.h>
 #include <Corrade/Utility/Format.h>
 
 namespace Cr = Corrade;
@@ -121,8 +122,14 @@ bool isLevelEnabled(Subsystem subsystem, LoggingLevel level) {
   return level >= LoggingContext::current().levelFor(subsystem);
 }
 
-Cr::Containers::String subsystemPrefix(Subsystem subsystem) {
-  return ""_s.join({"["_s, subsystemNames[uint8_t(subsystem)], "] "_s});
+Cr::Containers::String buildMessagePrefix(Subsystem subsystem,
+                                          const std::string& filename,
+                                          const std::string& function,
+                                          int line) {
+  auto baseFileName = Cr::Utility::Directory::filename(filename);
+  return ""_s.join({"["_s, subsystemNames[uint8_t(subsystem)], "] "_s,
+                    baseFileName.c_str(), "("_s, std::to_string(line).c_str(),
+                    ")::"_s, function.c_str(), " : "_s});
 }
 
 }  // namespace logging

src/esp/core/logging.h

@@ -241,9 +241,13 @@ class LoggingContext {
 bool isLevelEnabled(Subsystem subsystem, LoggingLevel level);
 
 /**
- * @brief Return the prefix that gets printed for a given subsystem in that log.
+ * @brief Build appropriate prefix for logging messages, including
+ * subsystem/namespace, file, line number and function name
  */
-Corrade::Containers::String subsystemPrefix(Subsystem subsystem);
+Corrade::Containers::String buildMessagePrefix(Subsystem subsystem,
+                                               const std::string& filename,
+                                               const std::string& function,
+                                               int line);
 
 namespace impl {
 class LogMessageVoidify {
@@ -301,7 +305,8 @@ class LogMessageVoidify {
 // 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::subsystemPrefix((subsystem))                        \
+      << esp::logging::buildMessagePrefix((subsystem), (__FILE__),         \
+                                          (__FUNCTION__), (__LINE__))      \
       << Corrade::Utility::Debug::nospace
 
 #define ESP_LOG_LEVEL_ENABLED(level) \

src/esp/core/managedContainers/ManagedContainer.h

@@ -129,8 +129,8 @@ class ManagedContainer : public ManagedContainerBase {
     if (nullptr == managedObject) {
       ESP_ERROR() << "<" << Corrade::Utility::Debug::nospace
                   << this->objectType_ << Corrade::Utility::Debug::nospace
-                  << ">::registerObject : Invalid "
-                     "(null) managed object passed to registration. Aborting.";
+                  << "> : Invalid (null) managed object passed to "
+                     "registration. Aborting.";
       return ID_UNDEFINED;
     }
     if ("" != objectHandle) {
@@ -141,9 +141,8 @@ class ManagedContainer : public ManagedContainerBase {
     if ("" == handleToSet) {
       ESP_ERROR() << "<" << Corrade::Utility::Debug::nospace
                   << this->objectType_ << Corrade::Utility::Debug::nospace
-                  << ">::registerObject : No "
-                     "valid handle specified for"
-                  << objectType_ << "managed object to register. Aborting.";
+                  << "> : No valid handle specified for" << objectType_
+                  << "managed object to register. Aborting.";
       return ID_UNDEFINED;
     }
     return registerObjectFinalize(managedObject, handleToSet,
@@ -617,9 +616,8 @@ auto ManagedContainer<T, Access>::removeObjectsBySubstring(
       getObjectHandlesBySubstring(subStr, contains);
   for (const std::string& objectHandle : handles) {
     int objID = this->getObjectIDByHandle(objectHandle);
-    ManagedPtr ptr = removeObjectInternal(
-        objID, objectHandle,
-        "<" + this->objectType_ + ">::removeObjectsBySubstring");
+    ManagedPtr ptr = removeObjectInternal(objID, objectHandle,
+                                          "<" + this->objectType_ + ">");
     if (nullptr != ptr) {
       res.push_back(ptr);
     }

src/esp/core/managedContainers/ManagedContainerBase.cpp

@@ -32,8 +32,7 @@ std::string ManagedContainerBase::getRandomObjectHandlePerType(
     const std::string& type) const {
   std::size_t numVals = mapOfHandles.size();
   if (numVals == 0) {
-    ESP_ERROR() << "::getRandomObjectHandlePerType : Attempting to get a random"
-                << type << objectType_
+    ESP_ERROR() << "Attempting to get a random" << type << objectType_
                 << "managed object handle but none are loaded; Aboring";
     return "";
   }
@@ -186,8 +185,7 @@ int ManagedContainerBase::getObjectIDByHandleOrNew(
   }
   if (!getNext) {
     ESP_ERROR() << "<" << Cr::Utility::Debug::nospace << this->objectType_
-                << Cr::Utility::Debug::nospace
-                << ">::getObjectIDByHandleOrNew : No" << objectType_
+                << Cr::Utility::Debug::nospace << "> : No" << objectType_
                 << "managed object with handle" << objectHandle
                 << "exists. Aborting";
     return ID_UNDEFINED;

src/esp/core/managedContainers/ManagedContainerBase.h

@@ -201,7 +201,7 @@ class ManagedContainerBase {
    */
   std::string getObjectHandleByID(const int objectID) const {
     if (objectLibKeyByID_.count(objectID) == 0) {
-      ESP_ERROR() << "::getObjectHandleByID : Unknown" << objectType_
+      ESP_ERROR() << "Unknown" << objectType_
                   << "managed object ID:" << objectID << ". Aborting";
       // never will have registered object with registration handle == ""
       return "";

src/esp/core/managedContainers/ManagedFileBasedContainer.h

@@ -72,9 +72,8 @@ class ManagedFileBasedContainer : public ManagedContainer<T, Access> {
     bool success = this->verifyLoadDocument(filename, docConfig);
     if (!success) {
       ESP_ERROR() << "<" << Magnum::Debug::nospace << this->objectType_
-                  << Magnum::Debug::nospace << ">::createObjectFromFile ("
-                  << this->objectType_
-                  << ") : Failure reading document as JSON :" << filename
+                  << Magnum::Debug::nospace
+                  << "> : Failure reading document as JSON :" << filename
                   << ". Aborting.";
       return nullptr;
     }
@@ -98,9 +97,8 @@ class ManagedFileBasedContainer : public ManagedContainer<T, Access> {
                                              CORRADE_UNUSED const U& config) {
     ESP_ERROR()
         << "<" << Magnum::Debug::nospace << this->objectType_
-        << Magnum::Debug::nospace << ">::buildManagedObjectFromDoc ("
-        << this->objectType_
-        << ") : Failure loading attributes from document of unknown type :"
+        << Magnum::Debug::nospace
+        << "> : Failure loading attributes from document of unknown type :"
         << filename << ". Aborting.";
   }
   /**
@@ -146,9 +144,8 @@ class ManagedFileBasedContainer : public ManagedContainer<T, Access> {
   bool verifyLoadDocument(const std::string& filename,
                           CORRADE_UNUSED U& resDoc) {
     // by here always fail
-    ESP_ERROR() << this->objectType_ << "<" << Magnum::Debug::nospace
-                << this->objectType_ << Magnum::Debug::nospace
-                << ">::verifyLoadDocument : File" << filename
+    ESP_ERROR() << "<" << Magnum::Debug::nospace << this->objectType_
+                << Magnum::Debug::nospace << "> : File" << filename
                 << "failed due to unknown file type.";
     return false;
   }  // ManagedContainerBase::verifyLoadDocument
@@ -211,16 +208,14 @@ std::string ManagedFileBasedContainer<T, Access>::convertFilenameToPassedExt(
     resHandle = Cr::Utility::Directory::splitExtension(filename).first + "." +
                 fileTypeExt;
     ESP_VERY_VERBOSE() << "<" << Magnum::Debug::nospace << this->objectType_
-                       << Magnum::Debug::nospace
-                       << ">::convertFilenameToPassedExt : Filename :"
-                       << filename << "changed to proposed" << fileTypeExt
+                       << Magnum::Debug::nospace << "> : Filename :" << filename
+                       << "changed to proposed" << fileTypeExt
                        << "filename :" << resHandle;
   } else {
     ESP_VERY_VERBOSE() << "<" << Magnum::Debug::nospace << this->objectType_
-                       << Magnum::Debug::nospace
-                       << ">::convertFilenameToPassedExt : Filename :"
-                       << filename << "contains requested file extension"
-                       << fileTypeExt << "already.";
+                       << Magnum::Debug::nospace << "> : Filename :" << filename
+                       << "contains requested file extension" << fileTypeExt
+                       << "already.";
   }
   return resHandle;
 }  // ManagedFileBasedContainer<T, Access>::convertFilenameToPassedExt
@@ -234,17 +229,16 @@ bool ManagedFileBasedContainer<T, Access>::verifyLoadDocument(
       jsonDoc = io::parseJsonFile(filename);
     } catch (...) {
       ESP_ERROR() << "<" << Magnum::Debug::nospace << this->objectType_
-                  << Magnum::Debug::nospace
-                  << ">::verifyLoadDocument : Failed to parse" << filename
+                  << Magnum::Debug::nospace << "> : Failed to parse" << filename
                   << "as JSON.";
       return false;
     }
     return true;
   } else {
     // by here always fail
     ESP_ERROR() << "<" << Magnum::Debug::nospace << this->objectType_
-                << Magnum::Debug::nospace << ">::verifyLoadDocument : File"
-                << filename << "does not exist";
+                << Magnum::Debug::nospace << "> : File" << filename
+                << "does not exist";
     return false;
   }
 }  // ManagedFileBasedContainer<T, Access>::verifyLoadDocument

src/esp/core/test/LoggingTest.cpp

@@ -57,24 +57,31 @@ constexpr const struct {
   const char* expected;
 } EnvVarTestData[]{
     {nullptr,
-     "[Default] DebugDefault\n[Default] WarningDefault\n"
-     "[Sim] DebugSim\n[Sim] WarningSim\n"
-     "[Gfx] "
-     "DebugGfx\n[Gfx] WarningGfx\n"},
+     "[Default] LoggingTest.cpp(101)::envVarTest : DebugDefault\n[Default] "
+     "LoggingTest.cpp(102)::envVarTest : WarningDefault\n"
+     "[Sim] LoggingTest.cpp(23)::debug : DebugSim\n[Sim] "
+     "LoggingTest.cpp(26)::warning : WarningSim\n"
+     "[Gfx] LoggingTest.cpp(36)::debug : DebugGfx\n[Gfx] "
+     "LoggingTest.cpp(39)::warning : WarningGfx\n"},
     {"debug",
-     "[Default] DebugDefault\n[Default] WarningDefault\n"
-     "[Sim] DebugSim\n[Sim] WarningSim\n"
-     "[Gfx] "
-     "DebugGfx\n[Gfx] WarningGfx\n"},
+     "[Default] LoggingTest.cpp(101)::envVarTest : DebugDefault\n[Default] "
+     "LoggingTest.cpp(102)::envVarTest : WarningDefault\n"
+     "[Sim] LoggingTest.cpp(23)::debug : DebugSim\n[Sim] "
+     "LoggingTest.cpp(26)::warning : WarningSim\n"
+     "[Gfx] LoggingTest.cpp(36)::debug : DebugGfx\n[Gfx] "
+     "LoggingTest.cpp(39)::warning : WarningGfx\n"},
     {"quiet", ""},
     {"error", ""},
     {"quiet:Sim,Gfx=verbose",
-     "[Sim] DebugSim\n[Sim] WarningSim\n[Gfx] "
-     "DebugGfx\n[Gfx] WarningGfx\n"},
+     "[Sim] LoggingTest.cpp(23)::debug : DebugSim\n[Sim] "
+     "LoggingTest.cpp(26)::warning : WarningSim\n[Gfx] "
+     "LoggingTest.cpp(36)::debug : DebugGfx\n[Gfx] "
+     "LoggingTest.cpp(39)::warning : WarningGfx\n"},
     {"warning:Gfx=debug",
-     "[Default] WarningDefault\n"
-     "[Sim] WarningSim\n[Gfx] "
-     "DebugGfx\n[Gfx] WarningGfx\n"},
+     "[Default] LoggingTest.cpp(102)::envVarTest : WarningDefault\n"
+     "[Sim] LoggingTest.cpp(26)::warning : WarningSim\n[Gfx] "
+     "LoggingTest.cpp(36)::debug : DebugGfx\n[Gfx] "
+     "LoggingTest.cpp(39)::warning : WarningGfx\n"},
 };  // namespace
 
 LoggingTest::LoggingTest() {

src/esp/io/URDFParser.cpp

@@ -112,13 +112,10 @@ bool Parser::parseURDF(std::shared_ptr<Model>& urdfModel,
   XMLDocument xml_doc;
   xml_doc.Parse(xmlString.c_str());
   if (xml_doc.Error()) {
-    ESP_ERROR()
-        << "Parser::parseURDF - XML parse error, aborting URDF parse/load for"
-        << filename;
+    ESP_ERROR() << "XML parse error, aborting URDF parse/load for" << filename;
     return false;
   }
-  ESP_VERY_VERBOSE()
-      << "Parser::parseURDF - XML parsed starting URDF parse/load.";
+  ESP_VERY_VERBOSE() << "XML parsed starting URDF parse/load.";
 
   const XMLElement* robot_xml = xml_doc.FirstChildElement("robot");
   if (!robot_xml) {
@@ -597,8 +594,7 @@ bool Parser::parseVisual(const std::shared_ptr<Model>& model,
           model->m_materials.at(visual.m_materialName);
       visual.m_geometry.m_hasLocalMaterial = true;
     } else {
-      ESP_VERY_VERBOSE() << "Warning: Parser::parseVisual : visual element \""
-                         << visual.m_name
+      ESP_VERY_VERBOSE() << "Warning: visual element \"" << visual.m_name
                          << "\" specified un-defined material name \""
                          << visual.m_materialName << "\".";
     }

src/esp/io/json.cpp

@@ -98,8 +98,7 @@ int loadJsonIntoConfiguration(const JsonGenericValue& jsonObj,
         // decrement count for key:obj due to not being handled vector
         --numConfigSettings;
         // TODO support numeric array in JSON
-        ESP_WARNING() << "::loadJsonIntoConfiguration : For subgroup name"
-                      << subGroupName
+        ESP_WARNING() << "For subgroup name" << subGroupName
                       << "config cell in JSON document contains key" << key
                       << "referencing an unsupported numeric array of length :"
                       << obj.Size() << "so skipping.";
@@ -117,8 +116,7 @@ int loadJsonIntoConfiguration(const JsonGenericValue& jsonObj,
       // TODO support other types?
       // decrement count for key:obj due to not being handled type
       --numConfigSettings;
-      ESP_WARNING() << "::loadJsonIntoConfiguration: For subgroup name"
-                    << subGroupName
+      ESP_WARNING() << "For subgroup name" << subGroupName
                     << "config cell in JSON document contains key" << key
                     << "referencing an unknown/unparsable value type, so "
                        "skipping this key.";