blob: fad602f5a9ac2566387b54477bd3835d14af3bc4 [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
Lei YUb50c7052021-01-21 16:02:26 +080069uint32_t Manager::commit(uint64_t transactionId, std::string errMsg)
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050070{
71 auto level = getLevel(errMsg);
72 _commit(transactionId, std::move(errMsg), level);
Lei YUb50c7052021-01-21 16:02:26 +080073 return entryId;
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050074}
75
Lei YUb50c7052021-01-21 16:02:26 +080076uint32_t Manager::commitWithLvl(uint64_t transactionId, std::string errMsg,
77 uint32_t errLvl)
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050078{
79 _commit(transactionId, std::move(errMsg),
80 static_cast<Entry::Level>(errLvl));
Lei YUb50c7052021-01-21 16:02:26 +080081 return entryId;
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050082}
83
Patrick Williamsa5171972021-04-16 20:10:01 -050084void Manager::_commit(uint64_t transactionId [[maybe_unused]],
85 std::string&& errMsg, Entry::Level errLvl)
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -050086{
Patrick Williamsa5171972021-04-16 20:10:01 -050087 std::vector<std::string> additionalData{};
88
89 // When running as a test-case, the system may have a LOT of journal
90 // data and we may not have permissions to do some of the journal sync
91 // operations. Just skip over them.
William A. Kennington IIIb6b25572021-05-19 17:09:41 -070092 if (!IS_UNIT_TEST)
Adriana Kobylakd311bc82016-10-16 09:54:40 -050093 {
William A. Kennington IIIb6b25572021-05-19 17:09:41 -070094 constexpr const auto transactionIdVar = "TRANSACTION_ID";
95 // Length of 'TRANSACTION_ID' string.
96 constexpr const auto transactionIdVarSize =
97 std::strlen(transactionIdVar);
98 // Length of 'TRANSACTION_ID=' string.
99 constexpr const auto transactionIdVarOffset = transactionIdVarSize + 1;
Adriana Kobylakd311bc82016-10-16 09:54:40 -0500100
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700101 // Flush all the pending log messages into the journal
102 journalSync();
Adriana Kobylak7298dc22017-01-24 12:21:50 -0600103
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700104 sd_journal* j = nullptr;
105 int rc = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY);
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600106 if (rc < 0)
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600107 {
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700108 logging::log<logging::level::ERR>(
109 "Failed to open journal",
110 logging::entry("DESCRIPTION=%s", strerror(-rc)));
111 return;
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600112 }
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600113
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700114 std::string transactionIdStr = std::to_string(transactionId);
115 std::set<std::string> metalist;
116 auto metamap = g_errMetaMap.find(errMsg);
117 if (metamap != g_errMetaMap.end())
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600118 {
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700119 metalist.insert(metamap->second.begin(), metamap->second.end());
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600120 }
121
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700122 // Add _PID field information in AdditionalData.
123 metalist.insert("_PID");
124
125 // Read the journal from the end to get the most recent entry first.
126 // The result from the sd_journal_get_data() is of the form
127 // VARIABLE=value.
128 SD_JOURNAL_FOREACH_BACKWARDS(j)
Adriana Kobylakfbe88722017-02-22 16:49:59 -0600129 {
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700130 const char* data = nullptr;
131 size_t length = 0;
132
133 // Look for the transaction id metadata variable
134 rc = sd_journal_get_data(j, transactionIdVar, (const void**)&data,
Patrick Venturef18bf832018-10-26 18:14:00 -0700135 &length);
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600136 if (rc < 0)
137 {
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700138 // This journal entry does not have the TRANSACTION_ID
139 // metadata variable.
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600140 continue;
141 }
142
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700143 // journald does not guarantee that sd_journal_get_data() returns
144 // NULL terminated strings, so need to specify the size to use to
145 // compare, use the returned length instead of anything that relies
146 // on NULL terminators like strlen(). The data variable is in the
147 // form of 'TRANSACTION_ID=1234'. Remove the TRANSACTION_ID
148 // characters plus the (=) sign to do the comparison. 'data +
149 // transactionIdVarOffset' will be in the form of '1234'. 'length -
150 // transactionIdVarOffset' will be the length of '1234'.
151 if ((length <= (transactionIdVarOffset)) ||
152 (transactionIdStr.compare(
153 0, transactionIdStr.size(), data + transactionIdVarOffset,
154 length - transactionIdVarOffset) != 0))
155 {
156 // The value of the TRANSACTION_ID metadata is not the requested
157 // transaction id number.
158 continue;
159 }
Adriana Kobylak9aa7d782017-02-18 09:20:49 -0600160
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700161 // Search for all metadata variables in the current journal entry.
162 for (auto i = metalist.cbegin(); i != metalist.cend();)
163 {
164 rc = sd_journal_get_data(j, (*i).c_str(), (const void**)&data,
165 &length);
166 if (rc < 0)
167 {
168 // Metadata variable not found, check next metadata
169 // variable.
170 i++;
171 continue;
172 }
Adriana Kobylakd311bc82016-10-16 09:54:40 -0500173
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700174 // Metadata variable found, save it and remove it from the set.
175 additionalData.emplace_back(data, length);
176 i = metalist.erase(i);
177 }
178 if (metalist.empty())
179 {
180 // All metadata variables found, break out of journal loop.
181 break;
182 }
183 }
184 if (!metalist.empty())
185 {
186 // Not all the metadata variables were found in the journal.
187 for (auto& metaVarStr : metalist)
188 {
189 logging::log<logging::level::INFO>(
190 "Failed to find metadata",
191 logging::entry("META_FIELD=%s", metaVarStr.c_str()));
192 }
193 }
194
195 sd_journal_close(j);
196 }
Matt Spinlerb60e7552019-07-24 15:28:08 -0500197 createEntry(errMsg, errLvl, additionalData);
198}
199
200void Manager::createEntry(std::string errMsg, Entry::Level errLvl,
Matt Spinlerc64b7122020-03-26 10:55:01 -0500201 std::vector<std::string> additionalData,
202 const FFDCEntries& ffdc)
Matt Spinlerb60e7552019-07-24 15:28:08 -0500203{
204 if (!Extensions::disableDefaultLogCaps())
205 {
206 if (errLvl < Entry::sevLowerLimit)
207 {
208 if (realErrors.size() >= ERROR_CAP)
209 {
210 erase(realErrors.front());
211 }
212 }
213 else
214 {
215 if (infoErrors.size() >= ERROR_INFO_CAP)
216 {
217 erase(infoErrors.front());
218 }
219 }
220 }
221
Adriana Kobylak4ea7f312017-01-10 12:52:34 -0600222 entryId++;
Deepak Kodihalli6fd9dc42018-04-03 02:08:42 -0500223 if (errLvl >= Entry::sevLowerLimit)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500224 {
225 infoErrors.push_back(entryId);
226 }
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600227 else
228 {
229 realErrors.push_back(entryId);
230 }
Adriana Kobylakc5f0bbd2017-01-22 14:56:04 -0600231 auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
Patrick Venturef18bf832018-10-26 18:14:00 -0700232 std::chrono::system_clock::now().time_since_epoch())
233 .count();
234 auto objPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entryId);
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600235
Patrick Venturef18bf832018-10-26 18:14:00 -0700236 AssociationList objects{};
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600237 processMetadata(errMsg, additionalData, objects);
238
Patrick Venturef18bf832018-10-26 18:14:00 -0700239 auto e = std::make_unique<Entry>(busLog, objPath, entryId,
240 ms, // Milliseconds since 1970
241 errLvl, std::move(errMsg),
242 std::move(additionalData),
243 std::move(objects), fwVersion, *this);
Adriana Kobylak1ff95ef2020-12-03 13:52:19 -0600244 auto path = serialize(*e);
245 e->path(path);
Matt Spinler99c2b402019-05-23 14:29:16 -0500246
Andrew Geissler32874542020-07-09 09:17:03 -0500247 if (isQuiesceOnErrorEnabled() && isCalloutPresent(*e))
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500248 {
Andrew Geissler32874542020-07-09 09:17:03 -0500249 quiesceOnError(entryId);
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500250 }
251
Adriana Kobylake7d271a2020-12-07 14:32:44 -0600252 // Add entry before calling the extensions so that they have access to it
253 entries.insert(std::make_pair(entryId, std::move(e)));
254
255 doExtensionLogCreate(*entries.find(entryId)->second, ffdc);
Matt Spinlerc64b7122020-03-26 10:55:01 -0500256
257 // Note: No need to close the file descriptors in the FFDC.
Adriana Kobylak1db1bd32016-10-10 11:39:20 -0500258}
259
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500260bool Manager::isQuiesceOnErrorEnabled()
261{
Patrick Williamsa5171972021-04-16 20:10:01 -0500262 // When running under tests, the Logging.Settings service will not be
263 // present. Assume false.
William A. Kennington IIIb6b25572021-05-19 17:09:41 -0700264 if (IS_UNIT_TEST)
265 {
266 return false;
267 }
Patrick Williamsa5171972021-04-16 20:10:01 -0500268
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500269 std::variant<bool> property;
270
271 auto method = this->busLog.new_method_call(
272 "xyz.openbmc_project.Settings", "/xyz/openbmc_project/logging/settings",
273 "org.freedesktop.DBus.Properties", "Get");
274
275 method.append("xyz.openbmc_project.Logging.Settings", "QuiesceOnHwError");
276
277 try
278 {
279 auto reply = this->busLog.call(method);
280 reply.read(property);
281 }
282 catch (const SdBusError& e)
283 {
284 log<level::ERR>("Error reading QuiesceOnHwError property",
285 entry("ERROR=%s", e.what()));
286 throw;
287 }
288
289 return std::get<bool>(property);
290}
291
Andrew Geisslere4960ee2020-03-30 14:31:52 -0500292bool Manager::isCalloutPresent(const Entry& entry)
293{
294 for (const auto& c : entry.additionalData())
295 {
296 if (c.find("CALLOUT_") != std::string::npos)
297 {
298 return true;
299 }
300 }
301
302 return false;
303}
304
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500305void Manager::findAndRemoveResolvedBlocks()
306{
307 for (auto& entry : entries)
308 {
309 if (entry.second->resolved())
310 {
311 checkAndRemoveBlockingError(entry.first);
312 }
313 }
314}
315
316void Manager::onEntryResolve(sdbusplus::message::message& msg)
317{
318 using Interface = std::string;
319 using Property = std::string;
320 using Value = std::string;
Patrick Williams25acc6c2020-06-02 11:05:34 -0500321 using Properties = std::map<Property, std::variant<Value>>;
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500322
323 Interface interface;
324 Properties properties;
325
326 msg.read(interface, properties);
327
328 for (const auto& p : properties)
329 {
330 if (p.first == "Resolved")
331 {
332 findAndRemoveResolvedBlocks();
333 return;
334 }
335 }
336}
337
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500338void Manager::checkAndQuiesceHost()
339{
Patrick Williamsa144a272021-07-16 17:03:55 -0500340 using Host = sdbusplus::xyz::openbmc_project::State::server::Host;
341
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500342 // First check host state
Patrick Williamsa144a272021-07-16 17:03:55 -0500343 std::variant<Host::HostState> property;
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500344
345 auto method = this->busLog.new_method_call(
346 "xyz.openbmc_project.State.Host", "/xyz/openbmc_project/state/host0",
347 "org.freedesktop.DBus.Properties", "Get");
348
349 method.append("xyz.openbmc_project.State.Host", "CurrentHostState");
350
351 try
352 {
353 auto reply = this->busLog.call(method);
354 reply.read(property);
355 }
356 catch (const SdBusError& e)
357 {
358 // Quiescing the host is a "best effort" type function. If unable to
359 // read the host state or it comes back empty, just return.
360 // The boot block object will still be created and the associations to
361 // find the log will be present. Don't want a dependency with
362 // phosphor-state-manager service
363 log<level::INFO>("Error reading QuiesceOnHwError property",
364 entry("ERROR=%s", e.what()));
365 return;
366 }
367
Patrick Williamsa144a272021-07-16 17:03:55 -0500368 auto hostState = std::get<Host::HostState>(property);
369 if (hostState != Host::HostState::Running)
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500370 {
371 return;
372 }
373
374 auto quiesce = this->busLog.new_method_call(
375 "org.freedesktop.systemd1", "/org/freedesktop/systemd1",
376 "org.freedesktop.systemd1.Manager", "StartUnit");
377
378 quiesce.append("obmc-host-quiesce@0.target");
379 quiesce.append("replace");
380
381 this->busLog.call_noreply(quiesce);
382}
383
Andrew Geissler32874542020-07-09 09:17:03 -0500384void Manager::quiesceOnError(const uint32_t entryId)
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500385{
Andrew Geissler72a1cca2020-09-10 16:49:09 -0500386 // Verify we don't already have this entry blocking
387 auto it = find_if(
388 this->blockingErrors.begin(), this->blockingErrors.end(),
389 [&](std::unique_ptr<Block>& obj) { return obj->entryId == entryId; });
390 if (it != this->blockingErrors.end())
391 {
392 // Already recorded so just return
393 logging::log<logging::level::DEBUG>(
394 "QuiesceOnError set and callout present but entry already logged");
395 return;
396 }
Andrew Geisslere4960ee2020-03-30 14:31:52 -0500397
Andrew Geisslere4960ee2020-03-30 14:31:52 -0500398 logging::log<logging::level::INFO>(
399 "QuiesceOnError set and callout present");
Andrew Geissler6a0ef6f2020-04-06 15:06:31 -0500400
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500401 auto blockPath =
Andrew Geissler32874542020-07-09 09:17:03 -0500402 std::string(OBJ_LOGGING) + "/block" + std::to_string(entryId);
403 auto blockObj = std::make_unique<Block>(this->busLog, blockPath, entryId);
Andrew Geissler6a0ef6f2020-04-06 15:06:31 -0500404 this->blockingErrors.push_back(std::move(blockObj));
405
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500406 // Register call back if log is resolved
407 using namespace sdbusplus::bus::match::rules;
Andrew Geissler32874542020-07-09 09:17:03 -0500408 auto entryPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entryId);
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500409 auto callback = std::make_unique<sdbusplus::bus::match::match>(
410 this->busLog,
411 propertiesChanged(entryPath, "xyz.openbmc_project.Logging.Entry"),
412 std::bind(std::mem_fn(&Manager::onEntryResolve), this,
413 std::placeholders::_1));
414
415 propChangedEntryCallback.insert(
Andrew Geissler32874542020-07-09 09:17:03 -0500416 std::make_pair(entryId, std::move(callback)));
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500417
Andrew Geisslerf6126a72020-05-08 10:41:09 -0500418 checkAndQuiesceHost();
Andrew Geisslerc0c500e2020-03-26 11:08:56 -0500419}
420
Matt Spinlerc64b7122020-03-26 10:55:01 -0500421void Manager::doExtensionLogCreate(const Entry& entry, const FFDCEntries& ffdc)
Matt Spinler99c2b402019-05-23 14:29:16 -0500422{
423 // Make the association <endpointpath>/<endpointtype> paths
424 std::vector<std::string> assocs;
425 for (const auto& [forwardType, reverseType, endpoint] :
426 entry.associations())
427 {
428 std::string e{endpoint};
429 e += '/' + reverseType;
430 assocs.push_back(e);
431 }
432
433 for (auto& create : Extensions::getCreateFunctions())
434 {
435 try
436 {
437 create(entry.message(), entry.id(), entry.timestamp(),
Matt Spinlerc64b7122020-03-26 10:55:01 -0500438 entry.severity(), entry.additionalData(), assocs, ffdc);
Matt Spinler99c2b402019-05-23 14:29:16 -0500439 }
440 catch (std::exception& e)
441 {
442 log<level::ERR>("An extension's create function threw an exception",
443 phosphor::logging::entry("ERROR=%s", e.what()));
444 }
445 }
446}
447
Patrick Williamsf40323d2021-04-16 15:35:17 -0500448void Manager::processMetadata(const std::string& /*errorName*/,
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600449 const std::vector<std::string>& additionalData,
450 AssociationList& objects) const
451{
452 // additionalData is a list of "metadata=value"
453 constexpr auto separator = '=';
Patrick Venture34438962018-10-30 13:17:37 -0700454 for (const auto& entryItem : additionalData)
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600455 {
Patrick Venture34438962018-10-30 13:17:37 -0700456 auto found = entryItem.find(separator);
Patrick Venturef18bf832018-10-26 18:14:00 -0700457 if (std::string::npos != found)
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600458 {
Patrick Venture34438962018-10-30 13:17:37 -0700459 auto metadata = entryItem.substr(0, found);
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600460 auto iter = meta.find(metadata);
Patrick Venturef18bf832018-10-26 18:14:00 -0700461 if (meta.end() != iter)
Deepak Kodihallia87c1572017-02-28 07:40:34 -0600462 {
463 (iter->second)(metadata, additionalData, objects);
464 }
465 }
466 }
467}
468
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500469void Manager::checkAndRemoveBlockingError(uint32_t entryId)
470{
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500471 // First look for blocking object and remove
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500472 auto it = find_if(
473 blockingErrors.begin(), blockingErrors.end(),
474 [&](std::unique_ptr<Block>& obj) { return obj->entryId == entryId; });
475 if (it != blockingErrors.end())
476 {
477 blockingErrors.erase(it);
478 }
Andrew Geissler7f6d4bc2020-04-16 14:47:34 -0500479
480 // Now remove the callback looking for the error to be resolved
481 auto resolveFind = propChangedEntryCallback.find(entryId);
482 if (resolveFind != propChangedEntryCallback.end())
483 {
484 propChangedEntryCallback.erase(resolveFind);
485 }
486
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500487 return;
488}
489
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500490void Manager::erase(uint32_t entryId)
491{
Patrick Venture34438962018-10-30 13:17:37 -0700492 auto entryFound = entries.find(entryId);
493 if (entries.end() != entryFound)
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500494 {
Matt Spinler99c2b402019-05-23 14:29:16 -0500495 for (auto& func : Extensions::getDeleteProhibitedFunctions())
496 {
497 try
498 {
499 bool prohibited = false;
500 func(entryId, prohibited);
501 if (prohibited)
502 {
503 // Future work remains to throw an error here.
504 return;
505 }
506 }
507 catch (std::exception& e)
508 {
509 log<level::ERR>(
510 "An extension's deleteProhibited function threw "
511 "an exception",
512 entry("ERROR=%s", e.what()));
513 }
514 }
515
Deepak Kodihalli33887992017-06-13 07:06:49 -0500516 // Delete the persistent representation of this error.
517 fs::path errorPath(ERRLOG_PERSIST_PATH);
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600518 errorPath /= std::to_string(entryId);
Deepak Kodihalli33887992017-06-13 07:06:49 -0500519 fs::remove(errorPath);
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600520
Patrick Venturef18bf832018-10-26 18:14:00 -0700521 auto removeId = [](std::list<uint32_t>& ids, uint32_t id) {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600522 auto it = std::find(ids.begin(), ids.end(), id);
523 if (it != ids.end())
524 {
525 ids.erase(it);
526 }
527 };
Patrick Venture34438962018-10-30 13:17:37 -0700528 if (entryFound->second->severity() >= Entry::sevLowerLimit)
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500529 {
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600530 removeId(infoErrors, entryId);
531 }
532 else
533 {
534 removeId(realErrors, entryId);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500535 }
Patrick Venture34438962018-10-30 13:17:37 -0700536 entries.erase(entryFound);
Matt Spinler99c2b402019-05-23 14:29:16 -0500537
Andrew Geisslerced6e2a2020-04-07 16:15:29 -0500538 checkAndRemoveBlockingError(entryId);
539
Matt Spinler99c2b402019-05-23 14:29:16 -0500540 for (auto& remove : Extensions::getDeleteFunctions())
541 {
542 try
543 {
544 remove(entryId);
545 }
546 catch (std::exception& e)
547 {
548 log<level::ERR>("An extension's delete function threw an "
549 "exception",
550 entry("ERROR=%s", e.what()));
551 }
552 }
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500553 }
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600554 else
555 {
556 logging::log<level::ERR>("Invalid entry ID to delete",
Patrick Venturef18bf832018-10-26 18:14:00 -0700557 logging::entry("ID=%d", entryId));
Marri Devender Rao8959efc2017-11-17 00:13:41 -0600558 }
Deepak Kodihalli99a85492017-03-31 06:01:57 -0500559}
560
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500561void Manager::restore()
562{
Patrick Venturef18bf832018-10-26 18:14:00 -0700563 auto sanity = [](const auto& id, const auto& restoredId) {
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600564 return id == restoredId;
565 };
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500566 std::vector<uint32_t> errorIds;
567
568 fs::path dir(ERRLOG_PERSIST_PATH);
569 if (!fs::exists(dir) || fs::is_empty(dir))
570 {
571 return;
572 }
573
Patrick Venturef18bf832018-10-26 18:14:00 -0700574 for (auto& file : fs::directory_iterator(dir))
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500575 {
576 auto id = file.path().filename().c_str();
577 auto idNum = std::stol(id);
578 auto e = std::make_unique<Entry>(
Patrick Venturef18bf832018-10-26 18:14:00 -0700579 busLog, std::string(OBJ_ENTRY) + '/' + id, idNum, *this);
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500580 if (deserialize(file.path(), *e))
581 {
Patrick Venturef18bf832018-10-26 18:14:00 -0700582 // validate the restored error entry id
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600583 if (sanity(static_cast<uint32_t>(idNum), e->id()))
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500584 {
Matt Spinleref952af2021-08-19 10:23:05 -0500585 e->path(file.path(), true);
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600586 e->emit_object_added();
587 if (e->severity() >= Entry::sevLowerLimit)
588 {
589 infoErrors.push_back(idNum);
590 }
Nagaraju Gorugantie4b0b772017-11-30 02:12:45 -0600591 else
592 {
593 realErrors.push_back(idNum);
594 }
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600595
596 entries.insert(std::make_pair(idNum, std::move(e)));
597 errorIds.push_back(idNum);
Nagaraju Gorugantif8a5a792017-10-13 08:09:52 -0500598 }
Marri Devender Rao979ed1c2017-11-17 05:06:25 -0600599 else
600 {
601 logging::log<logging::level::ERR>(
602 "Failed in sanity check while restoring error entry. "
603 "Ignoring error entry",
604 logging::entry("ID_NUM=%d", idNum),
605 logging::entry("ENTRY_ID=%d", e->id()));
606 }
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500607 }
608 }
609
Vishwanatha Subbanna37af9ba2017-09-28 16:33:53 +0530610 if (!errorIds.empty())
611 {
612 entryId = *(std::max_element(errorIds.begin(), errorIds.end()));
613 }
Deepak Kodihalli72654f12017-06-12 04:33:29 -0500614}
615
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500616void Manager::journalSync()
617{
618 bool syncRequested = false;
619 auto fd = -1;
620 auto rc = -1;
621 auto wd = -1;
622 auto bus = sdbusplus::bus::new_default();
623
624 auto start =
625 duration_cast<microseconds>(steady_clock::now().time_since_epoch())
626 .count();
627
Matthew Barth59913892019-08-27 15:43:48 -0500628 // Each time an error log is committed, a request to sync the journal
629 // must occur and block that error log commit until it completes. A 5sec
630 // block is done to allow sufficient time for the journal to be synced.
631 //
632 // Number of loop iterations = 3 for the following reasons:
633 // Iteration #1: Requests a journal sync by killing the journald service.
634 // Iteration #2: Setup an inotify watch to monitor the synced file that
635 // journald updates with the timestamp the last time the
636 // journal was flushed.
637 // Iteration #3: Poll to wait until inotify reports an event which blocks
638 // the error log from being commited until the sync completes.
639 constexpr auto maxRetry = 3;
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500640 for (int i = 0; i < maxRetry; i++)
641 {
642 // Read timestamp from synced file
643 constexpr auto syncedPath = "/run/systemd/journal/synced";
644 std::ifstream syncedFile(syncedPath);
645 if (syncedFile.fail())
646 {
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500647 // If the synced file doesn't exist, a sync request will create it.
648 if (errno != ENOENT)
649 {
650 log<level::ERR>("Failed to open journal synced file",
651 entry("FILENAME=%s", syncedPath),
652 entry("ERRNO=%d", errno));
653 return;
654 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500655 }
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500656 else
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500657 {
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500658 // Only read the synced file if it exists.
659 // See if a sync happened by now
660 std::string timestampStr;
661 std::getline(syncedFile, timestampStr);
Patrick Venture30047bf2018-11-01 18:52:15 -0700662 auto timestamp = std::stoll(timestampStr);
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500663 if (timestamp >= start)
664 {
Troy Leeb7f392a2019-11-19 14:34:56 +0800665 break;
Adriana Kobylak7d111a82018-09-04 10:14:24 -0500666 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500667 }
668
669 // Let's ask for a sync, but only once
670 if (!syncRequested)
671 {
672 syncRequested = true;
673
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500674 constexpr auto JOURNAL_UNIT = "systemd-journald.service";
675 auto signal = SIGRTMIN + 1;
676
677 auto method = bus.new_method_call(SYSTEMD_BUSNAME, SYSTEMD_PATH,
678 SYSTEMD_INTERFACE, "KillUnit");
679 method.append(JOURNAL_UNIT, "main", signal);
680 bus.call(method);
681 if (method.is_method_error())
682 {
683 log<level::ERR>("Failed to kill journal service");
Troy Leeb7f392a2019-11-19 14:34:56 +0800684 break;
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500685 }
Patrick Williamsa5171972021-04-16 20:10:01 -0500686
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500687 continue;
688 }
689
690 // Let's install the inotify watch, if we didn't do that yet. This watch
691 // monitors the syncedFile for when journald updates it with a newer
692 // timestamp. This means the journal has been flushed.
693 if (fd < 0)
694 {
695 fd = inotify_init1(IN_NONBLOCK | IN_CLOEXEC);
696 if (fd < 0)
697 {
698 log<level::ERR>("Failed to create inotify watch",
699 entry("ERRNO=%d", errno));
700 return;
701 }
702
703 constexpr auto JOURNAL_RUN_PATH = "/run/systemd/journal";
704 wd = inotify_add_watch(fd, JOURNAL_RUN_PATH,
705 IN_MOVED_TO | IN_DONT_FOLLOW | IN_ONLYDIR);
706 if (wd < 0)
707 {
708 log<level::ERR>("Failed to watch journal directory",
709 entry("PATH=%s", JOURNAL_RUN_PATH),
710 entry("ERRNO=%d", errno));
711 close(fd);
712 return;
713 }
714 continue;
715 }
716
717 // Let's wait until inotify reports an event
718 struct pollfd fds = {
Andrew Jefferyeb0aec42021-06-15 11:36:04 +0930719 fd,
720 POLLIN,
721 0,
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500722 };
723 constexpr auto pollTimeout = 5; // 5 seconds
724 rc = poll(&fds, 1, pollTimeout * 1000);
725 if (rc < 0)
726 {
727 log<level::ERR>("Failed to add event", entry("ERRNO=%d", errno),
728 entry("ERR=%s", strerror(-rc)));
729 inotify_rm_watch(fd, wd);
730 close(fd);
731 return;
732 }
733 else if (rc == 0)
734 {
735 log<level::INFO>("Poll timeout, no new journal synced data",
736 entry("TIMEOUT=%d", pollTimeout));
737 break;
738 }
739
740 // Read from the specified file descriptor until there is no new data,
741 // throwing away everything read since the timestamp will be read at the
742 // beginning of the loop.
743 constexpr auto maxBytes = 64;
744 uint8_t buffer[maxBytes];
745 while (read(fd, buffer, maxBytes) > 0)
746 ;
747 }
748
Adriana Kobylak4a029f22018-05-23 12:58:19 -0500749 if (fd != -1)
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500750 {
Adriana Kobylak4a029f22018-05-23 12:58:19 -0500751 if (wd != -1)
752 {
753 inotify_rm_watch(fd, wd);
754 }
Adriana Kobylak5f4247f2018-03-15 10:27:05 -0500755 close(fd);
756 }
757
758 return;
759}
760
Matt Spinler1275bd12018-05-01 15:13:53 -0500761std::string Manager::readFWVersion()
762{
Matt Spinlerf61f2922020-06-23 11:32:49 -0500763 auto version = util::getOSReleaseValue("VERSION_ID");
Matt Spinler1275bd12018-05-01 15:13:53 -0500764
Matt Spinlerf61f2922020-06-23 11:32:49 -0500765 if (!version)
Matt Spinler1275bd12018-05-01 15:13:53 -0500766 {
767 log<level::ERR>("Unable to read BMC firmware version");
768 }
769
Matt Spinlerf61f2922020-06-23 11:32:49 -0500770 return version.value_or("");
Matt Spinler1275bd12018-05-01 15:13:53 -0500771}
772
Matt Spinler3fb83b32019-07-26 11:22:44 -0500773void Manager::create(const std::string& message, Entry::Level severity,
774 const std::map<std::string, std::string>& additionalData)
775{
776 // Convert the map into a vector of "key=value" strings
777 std::vector<std::string> ad;
778 metadata::associations::combine(additionalData, ad);
779
780 createEntry(message, severity, ad);
781}
782
Matt Spinlerc64b7122020-03-26 10:55:01 -0500783void Manager::createWithFFDC(
784 const std::string& message, Entry::Level severity,
785 const std::map<std::string, std::string>& additionalData,
786 const FFDCEntries& ffdc)
787{
788 // Convert the map into a vector of "key=value" strings
789 std::vector<std::string> ad;
790 metadata::associations::combine(additionalData, ad);
791
792 createEntry(message, severity, ad, ffdc);
793}
794
Nagaraju Goruganti05aae8b2017-08-30 07:56:12 -0500795} // namespace internal
Adriana Kobylak8f7941e2016-11-14 14:46:23 -0600796} // namespace logging
Patrick Venturef18bf832018-10-26 18:14:00 -0700797} // namespace phosphor