1 #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"
8 #include "extensions.hpp"
9 #include "lib/lg2_commit.hpp"
10 #include "paths.hpp"
11 #include "util.hpp"
12 
13 #include <systemd/sd-bus.h>
14 #include <systemd/sd-journal.h>
15 #include <unistd.h>
16 
17 #include <phosphor-logging/lg2.hpp>
18 #include <sdbusplus/vtable.hpp>
19 #include <xyz/openbmc_project/State/Host/server.hpp>
20 
21 #include <cassert>
22 #include <chrono>
23 #include <cstdio>
24 #include <cstring>
25 #include <fstream>
26 #include <functional>
27 #include <future>
28 #include <iostream>
29 #include <map>
30 #include <set>
31 #include <string>
32 #include <string_view>
33 #include <vector>
34 
35 using namespace std::chrono;
36 extern const std::map<
37     phosphor::logging::metadata::Metadata,
38     std::function<phosphor::logging::metadata::associations::Type>>
39     meta;
40 
41 namespace phosphor
42 {
43 namespace logging
44 {
45 namespace internal
46 {
getLevel(const std::string & errMsg)47 inline auto getLevel(const std::string& errMsg)
48 {
49     auto reqLevel = Entry::Level::Error; // Default to Error
50 
51     auto levelmap = g_errLevelMap.find(errMsg);
52     if (levelmap != g_errLevelMap.end())
53     {
54         reqLevel = static_cast<Entry::Level>(levelmap->second);
55     }
56 
57     return reqLevel;
58 }
59 
getRealErrSize()60 int Manager::getRealErrSize()
61 {
62     return realErrors.size();
63 }
64 
getInfoErrSize()65 int Manager::getInfoErrSize()
66 {
67     return infoErrors.size();
68 }
69 
commit(uint64_t transactionId,std::string errMsg)70 uint32_t Manager::commit(uint64_t transactionId, std::string errMsg)
71 {
72     auto level = getLevel(errMsg);
73     _commit(transactionId, std::move(errMsg), level);
74     return entryId;
75 }
76 
commitWithLvl(uint64_t transactionId,std::string errMsg,uint32_t errLvl)77 uint32_t Manager::commitWithLvl(uint64_t transactionId, std::string errMsg,
78                                 uint32_t errLvl)
79 {
80     _commit(transactionId, std::move(errMsg),
81             static_cast<Entry::Level>(errLvl));
82     return entryId;
83 }
84 
_commit(uint64_t transactionId,std::string && errMsg,Entry::Level errLvl)85 void Manager::_commit(uint64_t transactionId [[maybe_unused]],
86                       std::string&& errMsg, Entry::Level errLvl)
87 {
88     std::vector<std::string> additionalData{};
89 
90     // When running as a test-case, the system may have a LOT of journal
91     // data and we may not have permissions to do some of the journal sync
92     // operations.  Just skip over them.
93     if (!IS_UNIT_TEST)
94     {
95         static constexpr auto transactionIdVar =
96             std::string_view{"TRANSACTION_ID"};
97         // Length of 'TRANSACTION_ID' string.
98         static constexpr auto transactionIdVarSize = transactionIdVar.size();
99         // Length of 'TRANSACTION_ID=' string.
100         static constexpr auto transactionIdVarOffset = transactionIdVarSize + 1;
101 
102         // Flush all the pending log messages into the journal
103         util::journalSync();
104 
105         sd_journal* j = nullptr;
106         int rc = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY);
107         if (rc < 0)
108         {
109             lg2::error("Failed to open journal: {ERROR}", "ERROR",
110                        strerror(-rc));
111             return;
112         }
113 
114         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())
118         {
119             metalist.insert(metamap->second.begin(), metamap->second.end());
120         }
121 
122         // 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)
129         {
130             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.data(),
135                                      (const void**)&data, &length);
136             if (rc < 0)
137             {
138                 // This journal entry does not have the TRANSACTION_ID
139                 // metadata variable.
140                 continue;
141             }
142 
143             // 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             }
160 
161             // 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                 }
173 
174                 // 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                 lg2::info("Failed to find metadata: {META_FIELD}", "META_FIELD",
190                           metaVarStr);
191             }
192         }
193 
194         sd_journal_close(j);
195     }
196     createEntry(errMsg, errLvl, additionalData);
197 }
198 
createEntry(std::string errMsg,Entry::Level errLvl,std::vector<std::string> additionalData,const FFDCEntries & ffdc)199 auto Manager::createEntry(
200     std::string errMsg, Entry::Level errLvl,
201     std::vector<std::string> additionalData,
202     const FFDCEntries& ffdc) -> sdbusplus::message::object_path
203 {
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 
222     entryId++;
223     if (errLvl >= Entry::sevLowerLimit)
224     {
225         infoErrors.push_back(entryId);
226     }
227     else
228     {
229         realErrors.push_back(entryId);
230     }
231     auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
232                   std::chrono::system_clock::now().time_since_epoch())
233                   .count();
234     auto objPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entryId);
235 
236     AssociationList objects{};
237     processMetadata(errMsg, additionalData, objects);
238 
239     auto e = std::make_unique<Entry>(
240         busLog, objPath, entryId,
241         ms, // Milliseconds since 1970
242         errLvl, std::move(errMsg), std::move(additionalData),
243         std::move(objects), fwVersion, getEntrySerializePath(entryId), *this);
244 
245     serialize(*e);
246 
247     if (isQuiesceOnErrorEnabled() && (errLvl < Entry::sevLowerLimit) &&
248         isCalloutPresent(*e))
249     {
250         quiesceOnError(entryId);
251     }
252 
253     // Add entry before calling the extensions so that they have access to it
254     entries.insert(std::make_pair(entryId, std::move(e)));
255 
256     doExtensionLogCreate(*entries.find(entryId)->second, ffdc);
257 
258     // Note: No need to close the file descriptors in the FFDC.
259 
260     return objPath;
261 }
262 
createFromEvent(sdbusplus::exception::generated_event_base && event)263 auto Manager::createFromEvent(sdbusplus::exception::generated_event_base&&
264                                   event) -> sdbusplus::message::object_path
265 {
266     auto [msg, level, data] = lg2::details::extractEvent(std::move(event));
267     return this->createEntry(msg, level, std::move(data));
268 }
269 
isQuiesceOnErrorEnabled()270 bool Manager::isQuiesceOnErrorEnabled()
271 {
272     // When running under tests, the Logging.Settings service will not be
273     // present.  Assume false.
274     if (IS_UNIT_TEST)
275     {
276         return false;
277     }
278 
279     std::variant<bool> property;
280 
281     auto method = this->busLog.new_method_call(
282         "xyz.openbmc_project.Settings", "/xyz/openbmc_project/logging/settings",
283         "org.freedesktop.DBus.Properties", "Get");
284 
285     method.append("xyz.openbmc_project.Logging.Settings", "QuiesceOnHwError");
286 
287     try
288     {
289         auto reply = this->busLog.call(method);
290         reply.read(property);
291     }
292     catch (const sdbusplus::exception_t& e)
293     {
294         lg2::error("Error reading QuiesceOnHwError property: {ERROR}", "ERROR",
295                    e);
296         return false;
297     }
298 
299     return std::get<bool>(property);
300 }
301 
isCalloutPresent(const Entry & entry)302 bool Manager::isCalloutPresent(const Entry& entry)
303 {
304     for (const auto& c : entry.additionalData())
305     {
306         if (c.find("CALLOUT_") != std::string::npos)
307         {
308             return true;
309         }
310     }
311 
312     return false;
313 }
314 
findAndRemoveResolvedBlocks()315 void Manager::findAndRemoveResolvedBlocks()
316 {
317     for (auto& entry : entries)
318     {
319         if (entry.second->resolved())
320         {
321             checkAndRemoveBlockingError(entry.first);
322         }
323     }
324 }
325 
onEntryResolve(sdbusplus::message_t & msg)326 void Manager::onEntryResolve(sdbusplus::message_t& msg)
327 {
328     using Interface = std::string;
329     using Property = std::string;
330     using Value = std::string;
331     using Properties = std::map<Property, std::variant<Value>>;
332 
333     Interface interface;
334     Properties properties;
335 
336     msg.read(interface, properties);
337 
338     for (const auto& p : properties)
339     {
340         if (p.first == "Resolved")
341         {
342             findAndRemoveResolvedBlocks();
343             return;
344         }
345     }
346 }
347 
checkAndQuiesceHost()348 void Manager::checkAndQuiesceHost()
349 {
350     using Host = sdbusplus::server::xyz::openbmc_project::state::Host;
351 
352     // First check host state
353     std::variant<Host::HostState> property;
354 
355     auto method = this->busLog.new_method_call(
356         "xyz.openbmc_project.State.Host", "/xyz/openbmc_project/state/host0",
357         "org.freedesktop.DBus.Properties", "Get");
358 
359     method.append("xyz.openbmc_project.State.Host", "CurrentHostState");
360 
361     try
362     {
363         auto reply = this->busLog.call(method);
364         reply.read(property);
365     }
366     catch (const sdbusplus::exception_t& e)
367     {
368         // Quiescing the host is a "best effort" type function. If unable to
369         // read the host state or it comes back empty, just return.
370         // The boot block object will still be created and the associations to
371         // find the log will be present. Don't want a dependency with
372         // phosphor-state-manager service
373         lg2::info("Error reading QuiesceOnHwError property: {ERROR}", "ERROR",
374                   e);
375         return;
376     }
377 
378     auto hostState = std::get<Host::HostState>(property);
379     if (hostState != Host::HostState::Running)
380     {
381         return;
382     }
383 
384     auto quiesce = this->busLog.new_method_call(
385         "org.freedesktop.systemd1", "/org/freedesktop/systemd1",
386         "org.freedesktop.systemd1.Manager", "StartUnit");
387 
388     quiesce.append("obmc-host-graceful-quiesce@0.target");
389     quiesce.append("replace");
390 
391     this->busLog.call_noreply(quiesce);
392 }
393 
quiesceOnError(const uint32_t entryId)394 void Manager::quiesceOnError(const uint32_t entryId)
395 {
396     // Verify we don't already have this entry blocking
397     auto it = find_if(this->blockingErrors.begin(), this->blockingErrors.end(),
398                       [&](const std::unique_ptr<Block>& obj) {
399                           return obj->entryId == entryId;
400                       });
401     if (it != this->blockingErrors.end())
402     {
403         // Already recorded so just return
404         lg2::debug(
405             "QuiesceOnError set and callout present but entry already logged");
406         return;
407     }
408 
409     lg2::info("QuiesceOnError set and callout present");
410 
411     auto blockPath =
412         std::string(OBJ_LOGGING) + "/block" + std::to_string(entryId);
413     auto blockObj = std::make_unique<Block>(this->busLog, blockPath, entryId);
414     this->blockingErrors.push_back(std::move(blockObj));
415 
416     // Register call back if log is resolved
417     using namespace sdbusplus::bus::match::rules;
418     auto entryPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entryId);
419     auto callback = std::make_unique<sdbusplus::bus::match_t>(
420         this->busLog,
421         propertiesChanged(entryPath, "xyz.openbmc_project.Logging.Entry"),
422         std::bind(std::mem_fn(&Manager::onEntryResolve), this,
423                   std::placeholders::_1));
424 
425     propChangedEntryCallback.insert(
426         std::make_pair(entryId, std::move(callback)));
427 
428     checkAndQuiesceHost();
429 }
430 
doExtensionLogCreate(const Entry & entry,const FFDCEntries & ffdc)431 void Manager::doExtensionLogCreate(const Entry& entry, const FFDCEntries& ffdc)
432 {
433     // Make the association <endpointpath>/<endpointtype> paths
434     std::vector<std::string> assocs;
435     for (const auto& [forwardType, reverseType, endpoint] :
436          entry.associations())
437     {
438         std::string e{endpoint};
439         e += '/' + reverseType;
440         assocs.push_back(e);
441     }
442 
443     for (auto& create : Extensions::getCreateFunctions())
444     {
445         try
446         {
447             create(entry.message(), entry.id(), entry.timestamp(),
448                    entry.severity(), entry.additionalData(), assocs, ffdc);
449         }
450         catch (const std::exception& e)
451         {
452             lg2::error(
453                 "An extension's create function threw an exception: {ERROR}",
454                 "ERROR", e);
455         }
456     }
457 }
458 
processMetadata(const std::string &,const std::vector<std::string> & additionalData,AssociationList & objects) const459 void Manager::processMetadata(const std::string& /*errorName*/,
460                               const std::vector<std::string>& additionalData,
461                               AssociationList& objects) const
462 {
463     // additionalData is a list of "metadata=value"
464     constexpr auto separator = '=';
465     for (const auto& entryItem : additionalData)
466     {
467         auto found = entryItem.find(separator);
468         if (std::string::npos != found)
469         {
470             auto metadata = entryItem.substr(0, found);
471             auto iter = meta.find(metadata);
472             if (meta.end() != iter)
473             {
474                 (iter->second)(metadata, additionalData, objects);
475             }
476         }
477     }
478 }
479 
checkAndRemoveBlockingError(uint32_t entryId)480 void Manager::checkAndRemoveBlockingError(uint32_t entryId)
481 {
482     // First look for blocking object and remove
483     auto it = find_if(blockingErrors.begin(), blockingErrors.end(),
484                       [&](const std::unique_ptr<Block>& obj) {
485                           return obj->entryId == entryId;
486                       });
487     if (it != blockingErrors.end())
488     {
489         blockingErrors.erase(it);
490     }
491 
492     // Now remove the callback looking for the error to be resolved
493     auto resolveFind = propChangedEntryCallback.find(entryId);
494     if (resolveFind != propChangedEntryCallback.end())
495     {
496         propChangedEntryCallback.erase(resolveFind);
497     }
498 
499     return;
500 }
501 
eraseAll()502 size_t Manager::eraseAll()
503 {
504     std::vector<uint32_t> logIDWithHwIsolation;
505     for (auto& func : Extensions::getLogIDWithHwIsolationFunctions())
506     {
507         try
508         {
509             func(logIDWithHwIsolation);
510         }
511         catch (const std::exception& e)
512         {
513             lg2::error("An extension's LogIDWithHwIsolation function threw an "
514                        "exception: {ERROR}",
515                        "ERROR", e);
516         }
517     }
518     size_t entriesSize = entries.size();
519     auto iter = entries.begin();
520     if (logIDWithHwIsolation.empty())
521     {
522         while (iter != entries.end())
523         {
524             auto e = iter->first;
525             ++iter;
526             erase(e);
527         }
528         entryId = 0;
529     }
530     else
531     {
532         while (iter != entries.end())
533         {
534             auto e = iter->first;
535             ++iter;
536             try
537             {
538                 if (!std::ranges::contains(logIDWithHwIsolation, e))
539                 {
540                     erase(e);
541                 }
542                 else
543                 {
544                     entriesSize--;
545                 }
546             }
547             catch (const sdbusplus::xyz::openbmc_project::Common::Error::
548                        Unavailable& e)
549             {
550                 entriesSize--;
551             }
552         }
553         if (!entries.empty())
554         {
555             entryId = std::ranges::max_element(entries, [](const auto& a,
556                                                            const auto& b) {
557                           return a.first < b.first;
558                       })->first;
559         }
560         else
561         {
562             entryId = 0;
563         }
564     }
565     return entriesSize;
566 }
567 
erase(uint32_t entryId)568 void Manager::erase(uint32_t entryId)
569 {
570     auto entryFound = entries.find(entryId);
571     if (entries.end() != entryFound)
572     {
573         for (auto& func : Extensions::getDeleteProhibitedFunctions())
574         {
575             try
576             {
577                 bool prohibited = false;
578                 func(entryId, prohibited);
579                 if (prohibited)
580                 {
581                     throw sdbusplus::xyz::openbmc_project::Common::Error::
582                         Unavailable();
583                 }
584             }
585             catch (const sdbusplus::xyz::openbmc_project::Common::Error::
586                        Unavailable& e)
587             {
588                 throw;
589             }
590             catch (const std::exception& e)
591             {
592                 lg2::error("An extension's deleteProhibited function threw an "
593                            "exception: {ERROR}",
594                            "ERROR", e);
595             }
596         }
597 
598         // Delete the persistent representation of this error.
599         fs::path errorPath(paths::error());
600         errorPath /= std::to_string(entryId);
601         fs::remove(errorPath);
602 
603         auto removeId = [](std::list<uint32_t>& ids, uint32_t id) {
604             auto it = std::find(ids.begin(), ids.end(), id);
605             if (it != ids.end())
606             {
607                 ids.erase(it);
608             }
609         };
610         if (entryFound->second->severity() >= Entry::sevLowerLimit)
611         {
612             removeId(infoErrors, entryId);
613         }
614         else
615         {
616             removeId(realErrors, entryId);
617         }
618         entries.erase(entryFound);
619 
620         checkAndRemoveBlockingError(entryId);
621 
622         for (auto& remove : Extensions::getDeleteFunctions())
623         {
624             try
625             {
626                 remove(entryId);
627             }
628             catch (const std::exception& e)
629             {
630                 lg2::error("An extension's delete function threw an exception: "
631                            "{ERROR}",
632                            "ERROR", e);
633             }
634         }
635     }
636     else
637     {
638         lg2::error("Invalid entry ID ({ID}) to delete", "ID", entryId);
639     }
640 }
641 
restore()642 void Manager::restore()
643 {
644     auto sanity = [](const auto& id, const auto& restoredId) {
645         return id == restoredId;
646     };
647 
648     fs::path dir(paths::error());
649     if (!fs::exists(dir) || fs::is_empty(dir))
650     {
651         return;
652     }
653 
654     for (auto& file : fs::directory_iterator(dir))
655     {
656         auto id = file.path().filename().c_str();
657         auto idNum = std::stol(id);
658         auto e = std::make_unique<Entry>(
659             busLog, std::string(OBJ_ENTRY) + '/' + id, idNum, *this);
660         if (deserialize(file.path(), *e))
661         {
662             // validate the restored error entry id
663             if (sanity(static_cast<uint32_t>(idNum), e->id()))
664             {
665                 e->path(file.path(), true);
666                 if (e->severity() >= Entry::sevLowerLimit)
667                 {
668                     infoErrors.push_back(idNum);
669                 }
670                 else
671                 {
672                     realErrors.push_back(idNum);
673                 }
674 
675                 entries.insert(std::make_pair(idNum, std::move(e)));
676             }
677             else
678             {
679                 lg2::error(
680                     "Failed in sanity check while restoring error entry. "
681                     "Ignoring error entry {ID_NUM}/{ENTRY_ID}.",
682                     "ID_NUM", idNum, "ENTRY_ID", e->id());
683             }
684         }
685     }
686 
687     if (!entries.empty())
688     {
689         entryId = entries.rbegin()->first;
690     }
691 }
692 
readFWVersion()693 std::string Manager::readFWVersion()
694 {
695     auto version = util::getOSReleaseValue("VERSION_ID");
696 
697     if (!version)
698     {
699         lg2::error("Unable to read BMC firmware version");
700     }
701 
702     return version.value_or("");
703 }
704 
create(const std::string & message,Entry::Level severity,const std::map<std::string,std::string> & additionalData,const FFDCEntries & ffdc)705 auto Manager::create(const std::string& message, Entry::Level severity,
706                      const std::map<std::string, std::string>& additionalData,
707                      const FFDCEntries& ffdc) -> sdbusplus::message::object_path
708 {
709     // Convert the map into a vector of "key=value" strings
710     std::vector<std::string> ad;
711     metadata::associations::combine(additionalData, ad);
712 
713     return createEntry(message, severity, ad, ffdc);
714 }
715 
716 } // namespace internal
717 } // namespace logging
718 } // namespace phosphor
719