From d047619b7003882846b108f519b00cdd41265361 Mon Sep 17 00:00:00 2001 From: P Dheeraj Srujan Kumar Date: Wed, 14 Jul 2021 14:13:11 +0000 Subject: [PATCH] Restructure Redfish EventLog Transmit code flow In the current implementation: 1. When Event service is disabled and enabled back after a while, all the logs during this time span between disable to enable are dumped to the Event listener. 2. When two events occur very close (in terms of microseconds) and they trigger two different iNotify events, the listener receives both of these events with the same Event ID. This occurs as the last log time stamp read from redfish file and previous time stamp used to generate Event ID's are not being updated continuously. This commit fixes this issue by tweaking the logic to continuously update the time stamp values (even during when Event Service is disabled), and also replaces multiple string operations with file operations. i.e. Instead of looping through the entire Redfish file until last time stamp read is reached, this fix makes use of fseek to get to the last read position. Tested: - Subscribed to an event and successfully received Event Logs. - No Event Logs were received when Event Service was disabled. - No Dump of past Events after Event Service was enabled. - Redfish Validator passed Change-Id: I87136bee78076b1b3219930813702b3b9d20c157 Signed-off-by: P Dheeraj Srujan Kumar --- .../include/event_service_manager.hpp | 108 ++++++++++++------ 1 file changed, 76 insertions(+), 32 deletions(-) diff --git a/redfish-core/include/event_service_manager.hpp b/redfish-core/include/event_service_manager.hpp index 3208fb3..86c90fb 100644 --- a/redfish-core/include/event_service_manager.hpp +++ b/redfish-core/include/event_service_manager.hpp @@ -134,15 +134,10 @@ static const Message* formatMessage(const std::string_view& messageID) namespace event_log { -inline bool getUniqueEntryID(const std::string& logEntry, std::string& entryID, - const bool firstEntry = true) +inline bool getUniqueEntryID(const std::string& logEntry, std::string& entryID) { static time_t prevTs = 0; static int index = 0; - if (firstEntry) - { - prevTs = 0; - } // Get the entry timestamp std::time_t curTs = 0; @@ -628,6 +623,7 @@ class EventServiceManager } std::string lastEventTStr; + std::streampos redfishLogFilePosition{0}; size_t noOfEventLogSubscribers{0}; size_t noOfMetricReportSubscribers{0}; std::shared_ptr matchTelemetryMonitor; @@ -1172,7 +1168,22 @@ class EventServiceManager #ifndef BMCWEB_ENABLE_REDFISH_DBUS_LOG_ENTRIES void cacheLastEventTimestamp() { - lastEventTStr.clear(); + // Control comes here when : + // 1. Subscription is added and lastEventTStr is empty + // 2. lastEventTStr is empty + // 3. When a new Redfish file is created + + if (!lastEventTStr.empty()) + { + // Control would be here when Redfish file is created. + // Reset File Position as new file is created + redfishLogFilePosition = 0; + return; + } + + // Open the redfish file and read till the last record to get the + // last event's time stamp. + std::ifstream logStream(redfishEventLogFile); if (!logStream.good()) { @@ -1180,27 +1191,44 @@ class EventServiceManager return; } std::string logEntry; + std::string prev_logEntry; while (std::getline(logStream, logEntry)) { - size_t space = logEntry.find_first_of(' '); - if (space == std::string::npos) - { - // Shouldn't enter here but lets skip it. - BMCWEB_LOG_DEBUG << "Invalid log entry found."; - continue; - } - lastEventTStr = logEntry.substr(0, space); + prev_logEntry = logEntry; + redfishLogFilePosition = logStream.tellg(); + } + + if (prev_logEntry.empty()) + { + BMCWEB_LOG_ERROR + << "Last Event Time Stamp Caching Failed : No Records"; + redfishLogFilePosition = 0; + return; + } + + size_t space = prev_logEntry.find_first_of(' '); + if (space == std::string::npos) + { + // Shouldn't enter here but lets skip it. + BMCWEB_LOG_DEBUG << "Invalid log entry found."; + BMCWEB_LOG_ERROR << "Last Event Time Stamp Caching Failed"; + return; } + lastEventTStr = prev_logEntry.substr(0, space); BMCWEB_LOG_DEBUG << "Last Event time stamp set: " << lastEventTStr; + BMCWEB_LOG_DEBUG << "Next Log Position : " << redfishLogFilePosition; } void readEventLogsFromFile() { - if (!serviceEnabled || !noOfEventLogSubscribers) + if (lastEventTStr.empty()) { - BMCWEB_LOG_DEBUG << "EventService disabled or no Subscriptions."; - return; + // Shouldn't ideally enter here. + // Last event Time stamp would be set by now. + // Just incase of any failures before. + cacheLastEventTimestamp(); } + std::ifstream logStream(redfishEventLogFile); if (!logStream.good()) { @@ -1210,27 +1238,21 @@ class EventServiceManager std::vector eventRecords; - bool startLogCollection = false; - bool firstEntry = true; - std::string logEntry; + + // Get the read pointer to the next log to be read. + logStream.seekg(redfishLogFilePosition); + while (std::getline(logStream, logEntry)) { - if (!startLogCollection && !lastEventTStr.empty()) - { - if (boost::starts_with(logEntry, lastEventTStr)) - { - startLogCollection = true; - } - continue; - } + // Update Pointer position + redfishLogFilePosition = logStream.tellg(); std::string idStr; - if (!event_log::getUniqueEntryID(logEntry, idStr, firstEntry)) + if (!event_log::getUniqueEntryID(logEntry, idStr)) { continue; } - firstEntry = false; std::string timestamp; std::string messageID; @@ -1242,6 +1264,16 @@ class EventServiceManager continue; } + lastEventTStr = timestamp; + + if (!serviceEnabled || !noOfEventLogSubscribers) + { + // If Service is not enabled, no need to compute + // the remaining items below. + // But, Loop must continue to keep track of Timestamp + continue; + } + std::string registryName; std::string messageKey; event_log::getRegistryAndMessageKey(messageID, registryName, @@ -1251,11 +1283,23 @@ class EventServiceManager continue; } - lastEventTStr = timestamp; eventRecords.emplace_back(idStr, timestamp, messageID, registryName, messageKey, messageArgs); } + if (!serviceEnabled || !noOfEventLogSubscribers) + { + BMCWEB_LOG_DEBUG << "EventService disabled or no Subscriptions."; + return; + } + + if (eventRecords.empty()) + { + // No Records to send + BMCWEB_LOG_DEBUG << "No log entries available to be transferred."; + return; + } + for (const auto& it : this->subscriptionsMap) { std::shared_ptr entry = it.second; -- 2.17.1