1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
|
From d047619b7003882846b108f519b00cdd41265361 Mon Sep 17 00:00:00 2001
From: P Dheeraj Srujan Kumar <p.dheeraj.srujan.kumar@intel.com>
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 <p.dheeraj.srujan.kumar@intel.com>
---
.../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<sdbusplus::bus::match::match> 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<EventLogObjectsType> 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<Subscription> entry = it.second;
--
2.17.1
|
