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