commit 03d4d37c2132d217b55ab5cc66fc61d5a7c2d3c1
author Alexander Hansen <alexander.hansen@9elements.com> Thu Aug 29 14:02:19 2024 +0200
committer Ed Tanous <ed@tanous.net> Tue Sep 10 16:36:39 2024 +0000
tree eda8da5efa1d1e748d4a84e9b5a0caf0c25bafc1
parent 1d19d872bb9195b8f1f340771c087ca43f756b5f

event service manager: more meaningful debug logs

When debugging event subscriptions, this helps to investigate where a
particular event was filtered or experienced some validation error.

Change-Id: If08ac5c7d2dea5921261a8a464d3ea6899615df5
Signed-off-by: Alexander Hansen <alexander.hansen@9elements.com>

redfish-core/include/event_service_manager.hpp

diff --git a/redfish-core/include/event_service_manager.hpp b/redfish-core/include/event_service_manager.hpp
index f1903d4..49112f2 100644
--- a/redfish-core/include/event_service_manager.hpp
+++ b/redfish-core/include/event_service_manager.hpp
@@ -162,6 +162,8 @@
     size_t space = logEntry.find_first_of(' ');
     if (space == std::string::npos)
     {
+        BMCWEB_LOG_ERROR("EventLog Params: could not find first space: {}",
+                         logEntry);
         return -EINVAL;
     }
     timestamp = logEntry.substr(0, space);
@@ -169,6 +171,8 @@
     size_t entryStart = logEntry.find_first_not_of(' ', space);
     if (entryStart == std::string::npos)
     {
+        BMCWEB_LOG_ERROR("EventLog Params: could not find log contents: {}",
+                         logEntry);
         return -EINVAL;
     }
     std::string_view entry(logEntry);
@@ -179,6 +183,8 @@
     // We need at least a MessageId to be valid
     if (logEntryFields.empty())
     {
+        BMCWEB_LOG_ERROR("EventLog Params: could not find entry fields: {}",
+                         logEntry);
         return -EINVAL;
     }
     messageID = logEntryFields[0];
@@ -336,6 +342,7 @@
             auto eventJson = eventMessage.find("MessageId");
             if (eventJson == eventMessage.end())
             {
+                BMCWEB_LOG_DEBUG("'MessageId' not present");
                 return false;
             }
 
@@ -352,9 +359,16 @@
             event_log::getRegistryAndMessageKey(*messageId, registry,
                                                 messageKey);
 
+            BMCWEB_LOG_DEBUG("extracted registry {}", registry);
+            BMCWEB_LOG_DEBUG("extracted message key {}", messageKey);
+
             auto obj = std::ranges::find(registryMsgIds, registry);
             if (obj == registryMsgIds.end())
             {
+                BMCWEB_LOG_DEBUG("did not find registry {} in registryMsgIds",
+                                 registry);
+                BMCWEB_LOG_DEBUG("registryMsgIds has {} entries",
+                                 registryMsgIds.size());
                 return false;
             }
         }
@@ -418,6 +432,8 @@
 
             if (!eventMatchesFilter(bmcLogEntry, ""))
             {
+                BMCWEB_LOG_DEBUG("Event {} did not match the filter",
+                                 nlohmann::json(bmcLogEntry).dump());
                 continue;
             }
 
@@ -1117,17 +1133,24 @@
 
         std::string logEntry;
 
+        BMCWEB_LOG_DEBUG("Redfish log file: seek to {}",
+                         static_cast<int>(redfishLogFilePosition));
+
         // Get the read pointer to the next log to be read.
         logStream.seekg(redfishLogFilePosition);
 
         while (std::getline(logStream, logEntry))
         {
+            BMCWEB_LOG_DEBUG("Redfish log file: found new event log entry");
             // Update Pointer position
             redfishLogFilePosition = logStream.tellg();
 
             std::string idStr;
             if (!event_log::getUniqueEntryID(logEntry, idStr))
             {
+                BMCWEB_LOG_DEBUG(
+                    "Redfish log file: could not get unique entry id for {}",
+                    logEntry);
                 continue;
             }
 
@@ -1136,6 +1159,8 @@
                 // If Service is not enabled, no need to compute
                 // the remaining items below.
                 // But, Loop must continue to keep track of Timestamp
+                BMCWEB_LOG_DEBUG(
+                    "Redfish log file: no subscribers / event service not enabled");
                 continue;
             }
 
@@ -1145,7 +1170,8 @@
             if (event_log::getEventLogParams(logEntry, timestamp, messageID,
                                              messageArgs) != 0)
             {
-                BMCWEB_LOG_DEBUG("Read eventLog entry params failed");
+                BMCWEB_LOG_DEBUG("Read eventLog entry params failed for {}",
+                                 logEntry);
                 continue;
             }
 
@@ -1179,6 +1205,7 @@
     {
         if (!inotifyConn)
         {
+            BMCWEB_LOG_ERROR("inotify Connection is not present");
             return;
         }
 
@@ -1198,6 +1225,9 @@
                     BMCWEB_LOG_ERROR("Callback Error: {}", ec.message());
                     return;
                 }
+
+                BMCWEB_LOG_DEBUG("reading {} via inotify", bytesTransferred);
+
                 std::size_t index = 0;
                 while ((index + iEventSize) <= bytesTransferred)
                 {
@@ -1277,6 +1307,8 @@
 
     static int startEventLogMonitor(boost::asio::io_context& ioc)
     {
+        BMCWEB_LOG_DEBUG("starting Event Log Monitor");
+
         inotifyConn.emplace(ioc);
         inotifyFd = inotify_init1(IN_NONBLOCK);
         if (inotifyFd == -1)