blob: bcc94a589e48506e159e5c1d7808323464e14c76 [file] [log] [blame]
Patrick Venturef18bf832018-10-26 18:14:00 -07001#include "config.h"
2
3#include "log_manager.hpp"
4
5#include "elog_entry.hpp"
6#include "elog_meta.hpp"
7#include "elog_serialize.hpp"
Matt Spinler99c2b402019-05-23 14:29:16 -05008#include "extensions.hpp"
Matt Spinlerf61f2922020-06-23 11:32:49 -05009#include "util.hpp"
Patrick Venturef18bf832018-10-26 18:14:00 -070010
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050011#include <poll.h>
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050012#include <sys/inotify.h>
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050013#include <systemd/sd-bus.h>
Adriana Kobylakd311bc82016-10-16 09:54:40 -050014#include <systemd/sd-journal.h>
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050015#include <unistd.h>
Patrick Venturef18bf832018-10-26 18:14:00 -070016
Matt Spinler99c2b402019-05-23 14:29:16 -050017#include <cassert>
Patrick Venturef18bf832018-10-26 18:14:00 -070018#include <chrono>
19#include <cstdio>
Patrick Venture30047bf2018-11-01 18:52:15 -070020#include <cstring>
Patrick Venturef18bf832018-10-26 18:14:00 -070021#include <fstream>
Patrick Venture30047bf2018-11-01 18:52:15 -070022#include <functional>
Patrick Venturef18bf832018-10-26 18:14:00 -070023#include <future>
24#include <iostream>
Patrick Venture30047bf2018-11-01 18:52:15 -070025#include <map>
Saqib Khan2bb15192017-02-13 13:19:55 -060026#include <phosphor-logging/log.hpp>
Patrick Venturef18bf832018-10-26 18:14:00 -070027#include <sdbusplus/vtable.hpp>
28#include <set>
29#include <string>
30#include <vector>
Andrew Geisslerf6126a72020-05-08 10:41:09 -050031#include <xyz/openbmc_project/State/Host/server.hpp>
Deepak Kodihallia87c1572017-02-28 07:40:34 -060032
33using namespace phosphor::logging;
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050034using namespace std::chrono;
Andrew Geisslerc0c500e2020-03-26 11:08:56 -050035using sdbusplus::exception::SdBusError;
Deepak Kodihallia87c1572017-02-28 07:40:34 -060036extern const std::map<metadata::Metadata,
Patrick Venturef18bf832018-10-26 18:14:00 -070037 std::function<metadata::associations::Type>>
38 meta;
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050039
Adriana Kobylak8f7941e2016-11-14 14:46:23 -060040namespace phosphor
41{
42namespace logging
43{
Nagaraju Goruganti05aae8b2017-08-30 07:56:12 -050044namespace internal
45{
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050046inline auto getLevel(const std::string& errMsg)
47{
48 auto reqLevel = Entry::Level::Error; // Default to Error
49
50 auto levelmap = g_errLevelMap.find(errMsg);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -050051 if (levelmap != g_errLevelMap.end())
Marri Devender Rao7656fba2017-08-06 05:42:52 -050052 {
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050053 reqLevel = static_cast<Entry::Level>(levelmap->second);
Marri Devender Rao7656fba2017-08-06 05:42:52 -050054 }
55
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050056 return reqLevel;
57}
58
Nagaraju Goruganti477b7312018-06-25 23:28:58 -050059int Manager::getRealErrSize()
60{
61 return realErrors.size();
62}
63
64int Manager::getInfoErrSize()
65{
66 return infoErrors.size();
67}
68
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050069void Manager::commit(uint64_t transactionId, std::string errMsg)
70{
71 auto level = getLevel(errMsg);
72 _commit(transactionId, std::move(errMsg), level);
73}
74
75void Manager::commitWithLvl(uint64_t transactionId, std::string errMsg,
76 uint32_t errLvl)
77{
78 _commit(transactionId, std::move(errMsg),
79 static_cast<Entry::Level>(errLvl));
80}
81
82void Manager::_commit(uint64_t transactionId, std::string&& errMsg,
83 Entry::Level errLvl)
84{
Adriana Kobylak7298dc22017-01-24 12:21:50 -060085 constexpr const auto transactionIdVar = "TRANSACTION_ID";
Adriana Kobylak27c87d92017-03-06 12:45:09 -060086 // Length of 'TRANSACTION_ID' string.
Patrick Venture30047bf2018-11-01 18:52:15 -070087 constexpr const auto transactionIdVarSize = std::strlen(transactionIdVar);
Adriana Kobylak27c87d92017-03-06 12:45:09 -060088 // Length of 'TRANSACTION_ID=' string.
89 constexpr const auto transactionIdVarOffset = transactionIdVarSize + 1;
Adriana Kobylak1db1bd32016-10-10 11:39:20 -050090
Adriana Kobylak5f4247f2018-03-15 10:27:05 -050091 // Flush all the pending log messages into the journal
92 journalSync();
Adriana Kobylakcfd9a7d2017-06-07 11:57:31 -050093
Patrick Venturef18bf832018-10-26 18:14:00 -070094 sd_journal* j = nullptr;
Adriana Kobylak8f7941e2016-11-14 14:46:23 -060095 int rc = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY);
Adriana Kobylakd311bc82016-10-16 09:54:40 -050096 if (rc < 0)
97 {
Patrick Venturef18bf832018-10-26 18:14:00 -070098 logging::log<logging::level::ERR>(
99 "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
Patrick Venturef18bf832018-10-26 18:14:00 -0700112 // Add _PID field information in AdditionalData.
Jayanth Othayothdb18ebe2017-09-04 00:48:02 -0500113 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 {
Patrick Venturef18bf832018-10-26 18:14:00 -0700121 const char* data = nullptr;
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600122 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
Patrick Venturef18bf832018-10-26 18:14:00 -0700125 rc = sd_journal_get_data(j, transactionIdVar, (const void**)&data,
126 &length);
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600127 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)) ||
Patrick Venturef18bf832018-10-26 18:14:00 -0700143 (transactionIdStr.compare(0, transactionIdStr.size(),
Adriana Kobylak27c87d92017-03-06 12:45:09 -0600144 data + transactionIdVarOffset,
145 length - transactionIdVarOffset) != 0))
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600146 {
147 // The value of the TRANSACTION_ID metadata is not the requested
148 // transaction id number.
149 continue;
150 }
151
152 // Search for all metadata variables in the current journal entry.
153 for (auto i = metalist.cbegin(); i != metalist.cend();)
154 {
Patrick Venturef18bf832018-10-26 18:14:00 -0700155 rc = sd_journal_get_data(j, (*i).c_str(), (const void**)&data,
156 &length);
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600157 if (rc < 0)
158 {
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600159 // Metadata variable not found, check next metadata variable.
160 i++;
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600161 continue;
162 }
163
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600164 // Metadata variable found, save it and remove it from the set.
165 additionalData.emplace_back(data, length);
166 i = metalist.erase(i);
167 }
168 if (metalist.empty())
169 {
170 // All metadata variables found, break out of journal loop.
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600171 break;
172 }
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600173 }
174 if (!metalist.empty())
175 {
176 // Not all the metadata variables were found in the journal.
177 for (auto& metaVarStr : metalist)
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600178 {
Patrick Venturef18bf832018-10-26 18:14:00 -0700179 logging::log<logging::level::INFO>(
180 "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
Matt Spinlerb60e7552019-07-24 15:28:08 -0500187 createEntry(errMsg, errLvl, additionalData);
188}
189
190void Manager::createEntry(std::string errMsg, Entry::Level errLvl,
Matt Spinlerc64b7122020-03-26 10:55:01 -0500191 std::vector<std::string> additionalData,
192 const FFDCEntries& ffdc)
Matt Spinlerb60e7552019-07-24 15:28:08 -0500193{
194 if (!Extensions::disableDefaultLogCaps())
195 {
196 if (errLvl < Entry::sevLowerLimit)
197 {
198 if (realErrors.size() >= ERROR_CAP)
199 {
200 erase(realErrors.front());
201 }
202 }
203 else
204 {
205 if (infoErrors.size() >= ERROR_INFO_CAP)
206 {
207 erase(infoErrors.front());
208 }
209 }
210 }
211
Adriana Kobylak4ea7f312017-01-10 12:52:34 -0600212 entryId++;
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -0500213 if (errLvl >= Entry::sevLowerLimit)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500214 {
215 infoErrors.push_back(entryId);
216 }
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600217 else
218 {
219 realErrors.push_back(entryId);
220 }
Adriana Kobylakc5f0bbd2017-01-22 14:56:04 -0600221 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
Patrick Venturef18bf832018-10-26 18:14:00 -0700222 std::chrono::system_clock::now().time_since_epoch())
223 .count();
224 auto objPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entryId);
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600225
Patrick Venturef18bf832018-10-26 18:14:00 -0700226 AssociationList objects{};
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600227 processMetadata(errMsg, additionalData, objects);
228
Patrick Venturef18bf832018-10-26 18:14:00 -0700229 auto e = std::make_unique<Entry>(busLog, objPath, entryId,
230 ms, // Milliseconds since 1970
231 errLvl, std::move(errMsg),
232 std::move(additionalData),
233 std::move(objects), fwVersion, *this);
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500234 serialize(*e);
Matt Spinler99c2b402019-05-23 14:29:16 -0500235
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500236 if (isQuiesceOnErrorEnabled())
237 {
238 checkQuiesceOnError(*e);
239 }
240
Matt Spinlerc64b7122020-03-26 10:55:01 -0500241 doExtensionLogCreate(*e, ffdc);
242
243 // Note: No need to close the file descriptors in the FFDC.
Matt Spinler99c2b402019-05-23 14:29:16 -0500244
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500245 entries.insert(std::make_pair(entryId, std::move(e)));
Adriana Kobylak1db1bd32016-10-10 11:39:20 -0500246}
247
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500248bool Manager::isQuiesceOnErrorEnabled()
249{
250 std::variant<bool> property;
251
252 auto method = this->busLog.new_method_call(
253 "xyz.openbmc_project.Settings", "/xyz/openbmc_project/logging/settings",
254 "org.freedesktop.DBus.Properties", "Get");
255
256 method.append("xyz.openbmc_project.Logging.Settings", "QuiesceOnHwError");
257
258 try
259 {
260 auto reply = this->busLog.call(method);
261 reply.read(property);
262 }
263 catch (const SdBusError& e)
264 {
265 log<level::ERR>("Error reading QuiesceOnHwError property",
266 entry("ERROR=%s", e.what()));
267 throw;
268 }
269
270 return std::get<bool>(property);
271}
272
Andrew Geisslere4960ee2020-03-30 14:31:52 -0500273bool Manager::isCalloutPresent(const Entry& entry)
274{
275 for (const auto& c : entry.additionalData())
276 {
277 if (c.find("CALLOUT_") != std::string::npos)
278 {
279 return true;
280 }
281 }
282
283 return false;
284}
285
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500286void Manager::findAndRemoveResolvedBlocks()
287{
288 for (auto& entry : entries)
289 {
290 if (entry.second->resolved())
291 {
292 checkAndRemoveBlockingError(entry.first);
293 }
294 }
295}
296
297void Manager::onEntryResolve(sdbusplus::message::message& msg)
298{
299 using Interface = std::string;
300 using Property = std::string;
301 using Value = std::string;
Patrick Williams25acc6c2020-06-02 11:05:34 -0500302 using Properties = std::map<Property, std::variant<Value>>;
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500303
304 Interface interface;
305 Properties properties;
306
307 msg.read(interface, properties);
308
309 for (const auto& p : properties)
310 {
311 if (p.first == "Resolved")
312 {
313 findAndRemoveResolvedBlocks();
314 return;
315 }
316 }
317}
318
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500319void Manager::checkAndQuiesceHost()
320{
321 // First check host state
322 std::variant<std::string> property;
323
324 auto method = this->busLog.new_method_call(
325 "xyz.openbmc_project.State.Host", "/xyz/openbmc_project/state/host0",
326 "org.freedesktop.DBus.Properties", "Get");
327
328 method.append("xyz.openbmc_project.State.Host", "CurrentHostState");
329
330 try
331 {
332 auto reply = this->busLog.call(method);
333 reply.read(property);
334 }
335 catch (const SdBusError& e)
336 {
337 // Quiescing the host is a "best effort" type function. If unable to
338 // read the host state or it comes back empty, just return.
339 // The boot block object will still be created and the associations to
340 // find the log will be present. Don't want a dependency with
341 // phosphor-state-manager service
342 log<level::INFO>("Error reading QuiesceOnHwError property",
343 entry("ERROR=%s", e.what()));
344 return;
345 }
346
347 std::string hostState = std::get<std::string>(property);
348
349 // If host state is empty, do nothing
350 if (hostState.empty())
351 {
352 return;
353 }
354
355 using Host = sdbusplus::xyz::openbmc_project::State::server::Host;
356 auto state = Host::convertHostStateFromString(hostState);
357 if (state != Host::HostState::Running)
358 {
359 return;
360 }
361
362 auto quiesce = this->busLog.new_method_call(
363 "org.freedesktop.systemd1", "/org/freedesktop/systemd1",
364 "org.freedesktop.systemd1.Manager", "StartUnit");
365
366 quiesce.append("obmc-host-quiesce@0.target");
367 quiesce.append("replace");
368
369 this->busLog.call_noreply(quiesce);
370}
371
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500372void Manager::checkQuiesceOnError(const Entry& entry)
373{
Andrew Geisslere4960ee2020-03-30 14:31:52 -0500374
375 if (!isCalloutPresent(entry))
376 {
377 return;
378 }
379
380 logging::log<logging::level::INFO>(
381 "QuiesceOnError set and callout present");
Andrew Geissler6a0ef6f2020-04-06 15:06:31 -0500382
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500383 auto blockPath =
384 std::string(OBJ_LOGGING) + "/block" + std::to_string(entry.id());
Andrew Geissler6a0ef6f2020-04-06 15:06:31 -0500385 auto blockObj =
386 std::make_unique<Block>(this->busLog, blockPath, entry.id());
387 this->blockingErrors.push_back(std::move(blockObj));
388
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500389 // Register call back if log is resolved
390 using namespace sdbusplus::bus::match::rules;
391 auto entryPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entry.id());
392 auto callback = std::make_unique<sdbusplus::bus::match::match>(
393 this->busLog,
394 propertiesChanged(entryPath, "xyz.openbmc_project.Logging.Entry"),
395 std::bind(std::mem_fn(&Manager::onEntryResolve), this,
396 std::placeholders::_1));
397
398 propChangedEntryCallback.insert(
399 std::make_pair(entry.id(), std::move(callback)));
400
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500401 checkAndQuiesceHost();
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500402}
403
Matt Spinlerc64b7122020-03-26 10:55:01 -0500404void Manager::doExtensionLogCreate(const Entry& entry, const FFDCEntries& ffdc)
Matt Spinler99c2b402019-05-23 14:29:16 -0500405{
406 // Make the association <endpointpath>/<endpointtype> paths
407 std::vector<std::string> assocs;
408 for (const auto& [forwardType, reverseType, endpoint] :
409 entry.associations())
410 {
411 std::string e{endpoint};
412 e += '/' + reverseType;
413 assocs.push_back(e);
414 }
415
416 for (auto& create : Extensions::getCreateFunctions())
417 {
418 try
419 {
420 create(entry.message(), entry.id(), entry.timestamp(),
Matt Spinlerc64b7122020-03-26 10:55:01 -0500421 entry.severity(), entry.additionalData(), assocs, ffdc);
Matt Spinler99c2b402019-05-23 14:29:16 -0500422 }
423 catch (std::exception& e)
424 {
425 log<level::ERR>("An extension's create function threw an exception",
426 phosphor::logging::entry("ERROR=%s", e.what()));
427 }
428 }
429}
430
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600431void Manager::processMetadata(const std::string& errorName,
432 const std::vector<std::string>& additionalData,
433 AssociationList& objects) const
434{
435 // additionalData is a list of "metadata=value"
436 constexpr auto separator = '=';
Patrick Venture34438962018-10-30 13:17:37 -0700437 for (const auto& entryItem : additionalData)
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600438 {
Patrick Venture34438962018-10-30 13:17:37 -0700439 auto found = entryItem.find(separator);
Patrick Venturef18bf832018-10-26 18:14:00 -0700440 if (std::string::npos != found)
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600441 {
Patrick Venture34438962018-10-30 13:17:37 -0700442 auto metadata = entryItem.substr(0, found);
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600443 auto iter = meta.find(metadata);
Patrick Venturef18bf832018-10-26 18:14:00 -0700444 if (meta.end() != iter)
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600445 {
446 (iter->second)(metadata, additionalData, objects);
447 }
448 }
449 }
450}
451
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500452void Manager::checkAndRemoveBlockingError(uint32_t entryId)
453{
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500454 // First look for blocking object and remove
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500455 auto it = find_if(
456 blockingErrors.begin(), blockingErrors.end(),
457 [&](std::unique_ptr<Block>& obj) { return obj->entryId == entryId; });
458 if (it != blockingErrors.end())
459 {
460 blockingErrors.erase(it);
461 }
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500462
463 // Now remove the callback looking for the error to be resolved
464 auto resolveFind = propChangedEntryCallback.find(entryId);
465 if (resolveFind != propChangedEntryCallback.end())
466 {
467 propChangedEntryCallback.erase(resolveFind);
468 }
469
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500470 return;
471}
472
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500473void Manager::erase(uint32_t entryId)
474{
Patrick Venture34438962018-10-30 13:17:37 -0700475 auto entryFound = entries.find(entryId);
476 if (entries.end() != entryFound)
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500477 {
Matt Spinler99c2b402019-05-23 14:29:16 -0500478 for (auto& func : Extensions::getDeleteProhibitedFunctions())
479 {
480 try
481 {
482 bool prohibited = false;
483 func(entryId, prohibited);
484 if (prohibited)
485 {
486 // Future work remains to throw an error here.
487 return;
488 }
489 }
490 catch (std::exception& e)
491 {
492 log<level::ERR>(
493 "An extension's deleteProhibited function threw "
494 "an exception",
495 entry("ERROR=%s", e.what()));
496 }
497 }
498
Deepak Kodihalli33887992017-06-13 07:06:49 -0500499 // Delete the persistent representation of this error.
500 fs::path errorPath(ERRLOG_PERSIST_PATH);
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600501 errorPath /= std::to_string(entryId);
Deepak Kodihalli33887992017-06-13 07:06:49 -0500502 fs::remove(errorPath);
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600503
Patrick Venturef18bf832018-10-26 18:14:00 -0700504 auto removeId = [](std::list<uint32_t>& ids, uint32_t id) {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600505 auto it = std::find(ids.begin(), ids.end(), id);
506 if (it != ids.end())
507 {
508 ids.erase(it);
509 }
510 };
Patrick Venture34438962018-10-30 13:17:37 -0700511 if (entryFound->second->severity() >= Entry::sevLowerLimit)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500512 {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600513 removeId(infoErrors, entryId);
514 }
515 else
516 {
517 removeId(realErrors, entryId);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500518 }
Patrick Venture34438962018-10-30 13:17:37 -0700519 entries.erase(entryFound);
Matt Spinler99c2b402019-05-23 14:29:16 -0500520
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500521 checkAndRemoveBlockingError(entryId);
522
Matt Spinler99c2b402019-05-23 14:29:16 -0500523 for (auto& remove : Extensions::getDeleteFunctions())
524 {
525 try
526 {
527 remove(entryId);
528 }
529 catch (std::exception& e)
530 {
531 log<level::ERR>("An extension's delete function threw an "
532 "exception",
533 entry("ERROR=%s", e.what()));
534 }
535 }
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500536 }
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600537 else
538 {
539 logging::log<level::ERR>("Invalid entry ID to delete",
Patrick Venturef18bf832018-10-26 18:14:00 -0700540 logging::entry("ID=%d", entryId));
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600541 }
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500542}
543
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500544void Manager::restore()
545{
Patrick Venturef18bf832018-10-26 18:14:00 -0700546 auto sanity = [](const auto& id, const auto& restoredId) {
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600547 return id == restoredId;
548 };
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500549 std::vector<uint32_t> errorIds;
550
551 fs::path dir(ERRLOG_PERSIST_PATH);
552 if (!fs::exists(dir) || fs::is_empty(dir))
553 {
554 return;
555 }
556
Patrick Venturef18bf832018-10-26 18:14:00 -0700557 for (auto& file : fs::directory_iterator(dir))
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500558 {
559 auto id = file.path().filename().c_str();
560 auto idNum = std::stol(id);
561 auto e = std::make_unique<Entry>(
Patrick Venturef18bf832018-10-26 18:14:00 -0700562 busLog, std::string(OBJ_ENTRY) + '/' + id, idNum, *this);
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500563 if (deserialize(file.path(), *e))
564 {
Patrick Venturef18bf832018-10-26 18:14:00 -0700565 // validate the restored error entry id
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600566 if (sanity(static_cast<uint32_t>(idNum), e->id()))
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500567 {
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600568 e->emit_object_added();
569 if (e->severity() >= Entry::sevLowerLimit)
570 {
571 infoErrors.push_back(idNum);
572 }
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600573 else
574 {
575 realErrors.push_back(idNum);
576 }
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600577
578 entries.insert(std::make_pair(idNum, std::move(e)));
579 errorIds.push_back(idNum);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500580 }
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600581 else
582 {
583 logging::log<logging::level::ERR>(
584 "Failed in sanity check while restoring error entry. "
585 "Ignoring error entry",
586 logging::entry("ID_NUM=%d", idNum),
587 logging::entry("ENTRY_ID=%d", e->id()));
588 }
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500589 }
590 }
591
Vishwanatha Subbanna37af9ba2017-09-28 16:33:53 +0530592 if (!errorIds.empty())
593 {
594 entryId = *(std::max_element(errorIds.begin(), errorIds.end()));
595 }
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500596}
597
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500598void Manager::journalSync()
599{
600 bool syncRequested = false;
601 auto fd = -1;
602 auto rc = -1;
603 auto wd = -1;
604 auto bus = sdbusplus::bus::new_default();
605
606 auto start =
607 duration_cast<microseconds>(steady_clock::now().time_since_epoch())
608 .count();
609
Matthew Barth59913892019-08-27 15:43:48 -0500610 // Each time an error log is committed, a request to sync the journal
611 // must occur and block that error log commit until it completes. A 5sec
612 // block is done to allow sufficient time for the journal to be synced.
613 //
614 // Number of loop iterations = 3 for the following reasons:
615 // Iteration #1: Requests a journal sync by killing the journald service.
616 // Iteration #2: Setup an inotify watch to monitor the synced file that
617 // journald updates with the timestamp the last time the
618 // journal was flushed.
619 // Iteration #3: Poll to wait until inotify reports an event which blocks
620 // the error log from being commited until the sync completes.
621 constexpr auto maxRetry = 3;
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500622 for (int i = 0; i < maxRetry; i++)
623 {
624 // Read timestamp from synced file
625 constexpr auto syncedPath = "/run/systemd/journal/synced";
626 std::ifstream syncedFile(syncedPath);
627 if (syncedFile.fail())
628 {
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500629 // If the synced file doesn't exist, a sync request will create it.
630 if (errno != ENOENT)
631 {
632 log<level::ERR>("Failed to open journal synced file",
633 entry("FILENAME=%s", syncedPath),
634 entry("ERRNO=%d", errno));
635 return;
636 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500637 }
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500638 else
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500639 {
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500640 // Only read the synced file if it exists.
641 // See if a sync happened by now
642 std::string timestampStr;
643 std::getline(syncedFile, timestampStr);
Patrick Venture30047bf2018-11-01 18:52:15 -0700644 auto timestamp = std::stoll(timestampStr);
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500645 if (timestamp >= start)
646 {
Troy Leeb7f392a2019-11-19 14:34:56 +0800647 break;
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500648 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500649 }
650
651 // Let's ask for a sync, but only once
652 if (!syncRequested)
653 {
654 syncRequested = true;
655
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500656 constexpr auto JOURNAL_UNIT = "systemd-journald.service";
657 auto signal = SIGRTMIN + 1;
658
659 auto method = bus.new_method_call(SYSTEMD_BUSNAME, SYSTEMD_PATH,
660 SYSTEMD_INTERFACE, "KillUnit");
661 method.append(JOURNAL_UNIT, "main", signal);
662 bus.call(method);
663 if (method.is_method_error())
664 {
665 log<level::ERR>("Failed to kill journal service");
Troy Leeb7f392a2019-11-19 14:34:56 +0800666 break;
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500667 }
668 continue;
669 }
670
671 // Let's install the inotify watch, if we didn't do that yet. This watch
672 // monitors the syncedFile for when journald updates it with a newer
673 // timestamp. This means the journal has been flushed.
674 if (fd < 0)
675 {
676 fd = inotify_init1(IN_NONBLOCK | IN_CLOEXEC);
677 if (fd < 0)
678 {
679 log<level::ERR>("Failed to create inotify watch",
680 entry("ERRNO=%d", errno));
681 return;
682 }
683
684 constexpr auto JOURNAL_RUN_PATH = "/run/systemd/journal";
685 wd = inotify_add_watch(fd, JOURNAL_RUN_PATH,
686 IN_MOVED_TO | IN_DONT_FOLLOW | IN_ONLYDIR);
687 if (wd < 0)
688 {
689 log<level::ERR>("Failed to watch journal directory",
690 entry("PATH=%s", JOURNAL_RUN_PATH),
691 entry("ERRNO=%d", errno));
692 close(fd);
693 return;
694 }
695 continue;
696 }
697
698 // Let's wait until inotify reports an event
699 struct pollfd fds = {
700 .fd = fd,
701 .events = POLLIN,
702 };
703 constexpr auto pollTimeout = 5; // 5 seconds
704 rc = poll(&fds, 1, pollTimeout * 1000);
705 if (rc < 0)
706 {
707 log<level::ERR>("Failed to add event", entry("ERRNO=%d", errno),
708 entry("ERR=%s", strerror(-rc)));
709 inotify_rm_watch(fd, wd);
710 close(fd);
711 return;
712 }
713 else if (rc == 0)
714 {
715 log<level::INFO>("Poll timeout, no new journal synced data",
716 entry("TIMEOUT=%d", pollTimeout));
717 break;
718 }
719
720 // Read from the specified file descriptor until there is no new data,
721 // throwing away everything read since the timestamp will be read at the
722 // beginning of the loop.
723 constexpr auto maxBytes = 64;
724 uint8_t buffer[maxBytes];
725 while (read(fd, buffer, maxBytes) > 0)
726 ;
727 }
728
Adriana Kobylak4a029f22018-05-23 12:58:19 -0500729 if (fd != -1)
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500730 {
Adriana Kobylak4a029f22018-05-23 12:58:19 -0500731 if (wd != -1)
732 {
733 inotify_rm_watch(fd, wd);
734 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500735 close(fd);
736 }
737
738 return;
739}
740
Matt Spinler1275bd12018-05-01 15:13:53 -0500741std::string Manager::readFWVersion()
742{
Matt Spinlerf61f2922020-06-23 11:32:49 -0500743 auto version = util::getOSReleaseValue("VERSION_ID");
Matt Spinler1275bd12018-05-01 15:13:53 -0500744
Matt Spinlerf61f2922020-06-23 11:32:49 -0500745 if (!version)
Matt Spinler1275bd12018-05-01 15:13:53 -0500746 {
747 log<level::ERR>("Unable to read BMC firmware version");
748 }
749
Matt Spinlerf61f2922020-06-23 11:32:49 -0500750 return version.value_or("");
Matt Spinler1275bd12018-05-01 15:13:53 -0500751}
752
Matt Spinler3fb83b32019-07-26 11:22:44 -0500753void Manager::create(const std::string& message, Entry::Level severity,
754 const std::map<std::string, std::string>& additionalData)
755{
756 // Convert the map into a vector of "key=value" strings
757 std::vector<std::string> ad;
758 metadata::associations::combine(additionalData, ad);
759
760 createEntry(message, severity, ad);
761}
762
Matt Spinlerc64b7122020-03-26 10:55:01 -0500763void Manager::createWithFFDC(
764 const std::string& message, Entry::Level severity,
765 const std::map<std::string, std::string>& additionalData,
766 const FFDCEntries& ffdc)
767{
768 // Convert the map into a vector of "key=value" strings
769 std::vector<std::string> ad;
770 metadata::associations::combine(additionalData, ad);
771
772 createEntry(message, severity, ad, ffdc);
773}
774
Nagaraju Goruganti05aae8b2017-08-30 07:56:12 -0500775} // namespace internal
Adriana Kobylak8f7941e2016-11-14 14:46:23 -0600776} // namespace logging
Patrick Venturef18bf832018-10-26 18:14:00 -0700777} // namespace phosphor