blob: ca48210267cd7dc43ecf544e5c526f0415b6aada [file] [log] [blame]
Adriana Kobylakd311bc82016-10-16 09:54:40 -05001#include <fstream>
Adriana Kobylak5f4247f2018-03-15 10:27:05 -05002#include <future>
Adriana Kobylakd311bc82016-10-16 09:54:40 -05003#include <iostream>
Adriana Kobylakc5f0bbd2017-01-22 14:56:04 -06004#include <chrono>
Adriana Kobylakd311bc82016-10-16 09:54:40 -05005#include <cstdio>
Adriana Kobylak5f4247f2018-03-15 10:27:05 -05006#include <poll.h>
Adriana Kobylakfbe88722017-02-22 16:49:59 -06007#include <set>
Adriana Kobylakd311bc82016-10-16 09:54:40 -05008#include <string>
9#include <vector>
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050010#include <sdbusplus/vtable.hpp>
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050011#include <sys/inotify.h>
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050012#include <systemd/sd-bus.h>
Adriana Kobylakd311bc82016-10-16 09:54:40 -050013#include <systemd/sd-journal.h>
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050014#include <unistd.h>
Adriana Kobylak4ea7f312017-01-10 12:52:34 -060015#include "config.h"
16#include "elog_entry.hpp"
Saqib Khan2bb15192017-02-13 13:19:55 -060017#include <phosphor-logging/log.hpp>
Adriana Kobylak8f7941e2016-11-14 14:46:23 -060018#include "log_manager.hpp"
Deepak Kodihallia87c1572017-02-28 07:40:34 -060019#include "elog_meta.hpp"
Deepak Kodihalli72654f12017-06-12 04:33:29 -050020#include "elog_serialize.hpp"
Deepak Kodihallia87c1572017-02-28 07:40:34 -060021
22using namespace phosphor::logging;
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050023using namespace std::chrono;
Deepak Kodihallia87c1572017-02-28 07:40:34 -060024extern const std::map<metadata::Metadata,
25 std::function<metadata::associations::Type>> meta;
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050026
Adriana Kobylak8f7941e2016-11-14 14:46:23 -060027namespace phosphor
28{
29namespace logging
30{
Nagaraju Goruganti05aae8b2017-08-30 07:56:12 -050031namespace internal
32{
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050033inline auto getLevel(const std::string& errMsg)
34{
35 auto reqLevel = Entry::Level::Error; // Default to Error
36
37 auto levelmap = g_errLevelMap.find(errMsg);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -050038 if (levelmap != g_errLevelMap.end())
Marri Devender Rao7656fba2017-08-06 05:42:52 -050039 {
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050040 reqLevel = static_cast<Entry::Level>(levelmap->second);
Marri Devender Rao7656fba2017-08-06 05:42:52 -050041 }
42
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050043 return reqLevel;
44}
45
Nagaraju Goruganti477b7312018-06-25 23:28:58 -050046int Manager::getRealErrSize()
47{
48 return realErrors.size();
49}
50
51int Manager::getInfoErrSize()
52{
53 return infoErrors.size();
54}
55
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050056void Manager::commit(uint64_t transactionId, std::string errMsg)
57{
58 auto level = getLevel(errMsg);
59 _commit(transactionId, std::move(errMsg), level);
60}
61
62void Manager::commitWithLvl(uint64_t transactionId, std::string errMsg,
63 uint32_t errLvl)
64{
65 _commit(transactionId, std::move(errMsg),
66 static_cast<Entry::Level>(errLvl));
67}
68
69void Manager::_commit(uint64_t transactionId, std::string&& errMsg,
70 Entry::Level errLvl)
71{
72 if (errLvl < Entry::sevLowerLimit)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -050073 {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -060074 if (realErrors.size() >= ERROR_CAP)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -050075 {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -060076 erase(realErrors.front());
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -050077 }
78 }
79 else
80 {
81 if (infoErrors.size() >= ERROR_INFO_CAP)
82 {
83 erase(infoErrors.front());
84 }
85 }
Adriana Kobylak7298dc22017-01-24 12:21:50 -060086 constexpr const auto transactionIdVar = "TRANSACTION_ID";
Adriana Kobylak27c87d92017-03-06 12:45:09 -060087 // Length of 'TRANSACTION_ID' string.
Adriana Kobylak67218992017-02-28 12:53:37 -060088 constexpr const auto transactionIdVarSize = strlen(transactionIdVar);
Adriana Kobylak27c87d92017-03-06 12:45:09 -060089 // Length of 'TRANSACTION_ID=' string.
90 constexpr const auto transactionIdVarOffset = transactionIdVarSize + 1;
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050091
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050092 // Flush all the pending log messages into the journal
93 journalSync();
Adriana Kobylakcfd9a7d2017-06-07 11:57:31 -050094
Adriana Kobylakd311bc82016-10-16 09:54:40 -050095 sd_journal *j = nullptr;
Adriana Kobylak8f7941e2016-11-14 14:46:23 -060096 int rc = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY);
Adriana Kobylakd311bc82016-10-16 09:54:40 -050097 if (rc < 0)
98 {
99 logging::log<logging::level::ERR>("Failed to open journal",
100 logging::entry("DESCRIPTION=%s", strerror(-rc)));
Adriana Kobylak8f7941e2016-11-14 14:46:23 -0600101 return;
Adriana Kobylakd311bc82016-10-16 09:54:40 -0500102 }
103
Adriana Kobylak7298dc22017-01-24 12:21:50 -0600104 std::string transactionIdStr = std::to_string(transactionId);
Adriana Kobylakd722b3a2017-02-28 12:10:44 -0600105 std::set<std::string> metalist;
106 auto metamap = g_errMetaMap.find(errMsg);
107 if (metamap != g_errMetaMap.end())
108 {
109 metalist.insert(metamap->second.begin(), metamap->second.end());
110 }
Adriana Kobylak7298dc22017-01-24 12:21:50 -0600111
Jayanth Othayothdb18ebe2017-09-04 00:48:02 -0500112 //Add _PID field information in AdditionalData.
113 metalist.insert("_PID");
114
Tom Joseph7a33ee42017-07-25 00:04:20 +0530115 std::vector<std::string> additionalData;
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600116
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600117 // Read the journal from the end to get the most recent entry first.
118 // The result from the sd_journal_get_data() is of the form VARIABLE=value.
119 SD_JOURNAL_FOREACH_BACKWARDS(j)
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600120 {
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600121 const char *data = nullptr;
122 size_t length = 0;
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600123
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600124 // Look for the transaction id metadata variable
125 rc = sd_journal_get_data(j, transactionIdVar, (const void **)&data,
126 &length);
127 if (rc < 0)
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600128 {
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600129 // This journal entry does not have the TRANSACTION_ID
130 // metadata variable.
131 continue;
132 }
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600133
Adriana Kobylak27c87d92017-03-06 12:45:09 -0600134 // journald does not guarantee that sd_journal_get_data() returns NULL
135 // terminated strings, so need to specify the size to use to compare,
136 // use the returned length instead of anything that relies on NULL
137 // terminators like strlen().
138 // The data variable is in the form of 'TRANSACTION_ID=1234'. Remove
139 // the TRANSACTION_ID characters plus the (=) sign to do the comparison.
140 // 'data + transactionIdVarOffset' will be in the form of '1234'.
141 // 'length - transactionIdVarOffset' will be the length of '1234'.
142 if ((length <= (transactionIdVarOffset)) ||
143 (transactionIdStr.compare(0,
144 transactionIdStr.size(),
145 data + transactionIdVarOffset,
146 length - transactionIdVarOffset) != 0))
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600147 {
148 // The value of the TRANSACTION_ID metadata is not the requested
149 // transaction id number.
150 continue;
151 }
152
153 // Search for all metadata variables in the current journal entry.
154 for (auto i = metalist.cbegin(); i != metalist.cend();)
155 {
156 rc = sd_journal_get_data(j, (*i).c_str(),
157 (const void **)&data, &length);
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600158 if (rc < 0)
159 {
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600160 // Metadata variable not found, check next metadata variable.
161 i++;
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600162 continue;
163 }
164
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600165 // Metadata variable found, save it and remove it from the set.
166 additionalData.emplace_back(data, length);
167 i = metalist.erase(i);
168 }
169 if (metalist.empty())
170 {
171 // All metadata variables found, break out of journal loop.
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600172 break;
173 }
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600174 }
175 if (!metalist.empty())
176 {
177 // Not all the metadata variables were found in the journal.
178 for (auto& metaVarStr : metalist)
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600179 {
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600180 logging::log<logging::level::INFO>("Failed to find metadata",
181 logging::entry("META_FIELD=%s", metaVarStr.c_str()));
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600182 }
183 }
184
Adriana Kobylakd311bc82016-10-16 09:54:40 -0500185 sd_journal_close(j);
186
Adriana Kobylak4ea7f312017-01-10 12:52:34 -0600187 // Create error Entry dbus object
188 entryId++;
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -0500189 if (errLvl >= Entry::sevLowerLimit)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500190 {
191 infoErrors.push_back(entryId);
192 }
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600193 else
194 {
195 realErrors.push_back(entryId);
196 }
Adriana Kobylakc5f0bbd2017-01-22 14:56:04 -0600197 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
198 std::chrono::system_clock::now().time_since_epoch()).count();
Adriana Kobylak4ea7f312017-01-10 12:52:34 -0600199 auto objPath = std::string(OBJ_ENTRY) + '/' +
Adriana Kobylakc5f0bbd2017-01-22 14:56:04 -0600200 std::to_string(entryId);
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600201
Deepak Kodihalli35b46372017-02-27 04:58:18 -0600202 AssociationList objects {};
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600203 processMetadata(errMsg, additionalData, objects);
204
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500205 auto e = std::make_unique<Entry>(
206 busLog,
207 objPath,
208 entryId,
209 ms, // Milliseconds since 1970
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -0500210 errLvl,
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500211 std::move(errMsg),
212 std::move(additionalData),
213 std::move(objects),
Matt Spinler375ac9b2018-05-01 15:20:55 -0500214 fwVersion,
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500215 *this);
216 serialize(*e);
217 entries.insert(std::make_pair(entryId, std::move(e)));
Adriana Kobylak1db1bd32016-10-10 11:39:20 -0500218}
219
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600220void Manager::processMetadata(const std::string& errorName,
221 const std::vector<std::string>& additionalData,
222 AssociationList& objects) const
223{
224 // additionalData is a list of "metadata=value"
225 constexpr auto separator = '=';
226 for(const auto& entry: additionalData)
227 {
228 auto found = entry.find(separator);
229 if(std::string::npos != found)
230 {
231 auto metadata = entry.substr(0, found);
232 auto iter = meta.find(metadata);
233 if(meta.end() != iter)
234 {
235 (iter->second)(metadata, additionalData, objects);
236 }
237 }
238 }
239}
240
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500241void Manager::erase(uint32_t entryId)
242{
243 auto entry = entries.find(entryId);
244 if(entries.end() != entry)
245 {
Deepak Kodihalli33887992017-06-13 07:06:49 -0500246 // Delete the persistent representation of this error.
247 fs::path errorPath(ERRLOG_PERSIST_PATH);
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600248 errorPath /= std::to_string(entryId);
Deepak Kodihalli33887992017-06-13 07:06:49 -0500249 fs::remove(errorPath);
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600250
251 auto removeId = [](std::list<uint32_t>& ids , uint32_t id)
252 {
253 auto it = std::find(ids.begin(), ids.end(), id);
254 if (it != ids.end())
255 {
256 ids.erase(it);
257 }
258 };
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500259 if (entry->second->severity() >= Entry::sevLowerLimit)
260 {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600261 removeId(infoErrors, entryId);
262 }
263 else
264 {
265 removeId(realErrors, entryId);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500266 }
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500267 entries.erase(entry);
268 }
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600269 else
270 {
271 logging::log<level::ERR>("Invalid entry ID to delete",
272 logging::entry("ID=%d", entryId));
273 }
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500274}
275
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500276void Manager::restore()
277{
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600278 auto sanity = [](const auto& id, const auto& restoredId)
279 {
280 return id == restoredId;
281 };
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500282 std::vector<uint32_t> errorIds;
283
284 fs::path dir(ERRLOG_PERSIST_PATH);
285 if (!fs::exists(dir) || fs::is_empty(dir))
286 {
287 return;
288 }
289
290 for(auto& file: fs::directory_iterator(dir))
291 {
292 auto id = file.path().filename().c_str();
293 auto idNum = std::stol(id);
294 auto e = std::make_unique<Entry>(
295 busLog,
296 std::string(OBJ_ENTRY) + '/' + id,
297 idNum,
298 *this);
299 if (deserialize(file.path(), *e))
300 {
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600301 //validate the restored error entry id
302 if (sanity(static_cast<uint32_t>(idNum), e->id()))
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500303 {
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600304 e->emit_object_added();
305 if (e->severity() >= Entry::sevLowerLimit)
306 {
307 infoErrors.push_back(idNum);
308 }
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600309 else
310 {
311 realErrors.push_back(idNum);
312 }
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600313
314 entries.insert(std::make_pair(idNum, std::move(e)));
315 errorIds.push_back(idNum);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500316 }
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600317 else
318 {
319 logging::log<logging::level::ERR>(
320 "Failed in sanity check while restoring error entry. "
321 "Ignoring error entry",
322 logging::entry("ID_NUM=%d", idNum),
323 logging::entry("ENTRY_ID=%d", e->id()));
324 }
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500325 }
326 }
327
Vishwanatha Subbanna37af9ba2017-09-28 16:33:53 +0530328 if (!errorIds.empty())
329 {
330 entryId = *(std::max_element(errorIds.begin(), errorIds.end()));
331 }
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500332}
333
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500334void Manager::journalSync()
335{
336 bool syncRequested = false;
337 auto fd = -1;
338 auto rc = -1;
339 auto wd = -1;
340 auto bus = sdbusplus::bus::new_default();
341
342 auto start =
343 duration_cast<microseconds>(steady_clock::now().time_since_epoch())
344 .count();
345
346 constexpr auto maxRetry = 2;
347 for (int i = 0; i < maxRetry; i++)
348 {
349 // Read timestamp from synced file
350 constexpr auto syncedPath = "/run/systemd/journal/synced";
351 std::ifstream syncedFile(syncedPath);
352 if (syncedFile.fail())
353 {
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500354 // If the synced file doesn't exist, a sync request will create it.
355 if (errno != ENOENT)
356 {
357 log<level::ERR>("Failed to open journal synced file",
358 entry("FILENAME=%s", syncedPath),
359 entry("ERRNO=%d", errno));
360 return;
361 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500362 }
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500363 else
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500364 {
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500365 // Only read the synced file if it exists.
366 // See if a sync happened by now
367 std::string timestampStr;
368 std::getline(syncedFile, timestampStr);
369 auto timestamp = stoll(timestampStr);
370 if (timestamp >= start)
371 {
372 return;
373 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500374 }
375
376 // Let's ask for a sync, but only once
377 if (!syncRequested)
378 {
379 syncRequested = true;
380
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500381 constexpr auto JOURNAL_UNIT = "systemd-journald.service";
382 auto signal = SIGRTMIN + 1;
383
384 auto method = bus.new_method_call(SYSTEMD_BUSNAME, SYSTEMD_PATH,
385 SYSTEMD_INTERFACE, "KillUnit");
386 method.append(JOURNAL_UNIT, "main", signal);
387 bus.call(method);
388 if (method.is_method_error())
389 {
390 log<level::ERR>("Failed to kill journal service");
391 return;
392 }
393 continue;
394 }
395
396 // Let's install the inotify watch, if we didn't do that yet. This watch
397 // monitors the syncedFile for when journald updates it with a newer
398 // timestamp. This means the journal has been flushed.
399 if (fd < 0)
400 {
401 fd = inotify_init1(IN_NONBLOCK | IN_CLOEXEC);
402 if (fd < 0)
403 {
404 log<level::ERR>("Failed to create inotify watch",
405 entry("ERRNO=%d", errno));
406 return;
407 }
408
409 constexpr auto JOURNAL_RUN_PATH = "/run/systemd/journal";
410 wd = inotify_add_watch(fd, JOURNAL_RUN_PATH,
411 IN_MOVED_TO | IN_DONT_FOLLOW | IN_ONLYDIR);
412 if (wd < 0)
413 {
414 log<level::ERR>("Failed to watch journal directory",
415 entry("PATH=%s", JOURNAL_RUN_PATH),
416 entry("ERRNO=%d", errno));
417 close(fd);
418 return;
419 }
420 continue;
421 }
422
423 // Let's wait until inotify reports an event
424 struct pollfd fds = {
425 .fd = fd,
426 .events = POLLIN,
427 };
428 constexpr auto pollTimeout = 5; // 5 seconds
429 rc = poll(&fds, 1, pollTimeout * 1000);
430 if (rc < 0)
431 {
432 log<level::ERR>("Failed to add event", entry("ERRNO=%d", errno),
433 entry("ERR=%s", strerror(-rc)));
434 inotify_rm_watch(fd, wd);
435 close(fd);
436 return;
437 }
438 else if (rc == 0)
439 {
440 log<level::INFO>("Poll timeout, no new journal synced data",
441 entry("TIMEOUT=%d", pollTimeout));
442 break;
443 }
444
445 // Read from the specified file descriptor until there is no new data,
446 // throwing away everything read since the timestamp will be read at the
447 // beginning of the loop.
448 constexpr auto maxBytes = 64;
449 uint8_t buffer[maxBytes];
450 while (read(fd, buffer, maxBytes) > 0)
451 ;
452 }
453
Adriana Kobylak4a029f22018-05-23 12:58:19 -0500454 if (fd != -1)
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500455 {
Adriana Kobylak4a029f22018-05-23 12:58:19 -0500456 if (wd != -1)
457 {
458 inotify_rm_watch(fd, wd);
459 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500460 close(fd);
461 }
462
463 return;
464}
465
Matt Spinler1275bd12018-05-01 15:13:53 -0500466std::string Manager::readFWVersion()
467{
468 std::string version;
469 std::ifstream versionFile{BMC_VERSION_FILE};
470 std::string line;
471 static constexpr auto VERSION_ID = "VERSION_ID=";
472
473 while (std::getline(versionFile, line))
474 {
475 if (line.find(VERSION_ID) != std::string::npos)
476 {
477 auto pos = line.find_first_of('"') + 1;
478 version = line.substr(pos, line.find_last_of('"') - pos);
479 break;
480 }
481 }
482
483 if (version.empty())
484 {
485 log<level::ERR>("Unable to read BMC firmware version");
486 }
487
488 return version;
489}
490
Nagaraju Goruganti05aae8b2017-08-30 07:56:12 -0500491} // namespace internal
Adriana Kobylak8f7941e2016-11-14 14:46:23 -0600492} // namespace logging
493} // namepsace phosphor