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 
9 #include <poll.h>
10 #include <sys/inotify.h>
11 #include <systemd/sd-bus.h>
12 #include <systemd/sd-journal.h>
13 #include <unistd.h>
14 
15 #include <chrono>
16 #include <cstdio>
17 #include <cstring>
18 #include <fstream>
19 #include <functional>
20 #include <future>
21 #include <iostream>
22 #include <map>
23 #include <phosphor-logging/log.hpp>
24 #include <sdbusplus/vtable.hpp>
25 #include <set>
26 #include <string>
27 #include <vector>
28 
29 using namespace phosphor::logging;
30 using namespace std::chrono;
31 extern const std::map<metadata::Metadata,
32                       std::function<metadata::associations::Type>>
33     meta;
34 
35 namespace phosphor
36 {
37 namespace logging
38 {
39 namespace internal
40 {
41 inline auto getLevel(const std::string& errMsg)
42 {
43     auto reqLevel = Entry::Level::Error; // Default to Error
44 
45     auto levelmap = g_errLevelMap.find(errMsg);
46     if (levelmap != g_errLevelMap.end())
47     {
48         reqLevel = static_cast<Entry::Level>(levelmap->second);
49     }
50 
51     return reqLevel;
52 }
53 
54 int Manager::getRealErrSize()
55 {
56     return realErrors.size();
57 }
58 
59 int Manager::getInfoErrSize()
60 {
61     return infoErrors.size();
62 }
63 
64 void Manager::commit(uint64_t transactionId, std::string errMsg)
65 {
66     auto level = getLevel(errMsg);
67     _commit(transactionId, std::move(errMsg), level);
68 }
69 
70 void Manager::commitWithLvl(uint64_t transactionId, std::string errMsg,
71                             uint32_t errLvl)
72 {
73     _commit(transactionId, std::move(errMsg),
74             static_cast<Entry::Level>(errLvl));
75 }
76 
77 void Manager::_commit(uint64_t transactionId, std::string&& errMsg,
78                       Entry::Level errLvl)
79 {
80     if (errLvl < Entry::sevLowerLimit)
81     {
82         if (realErrors.size() >= ERROR_CAP)
83         {
84             erase(realErrors.front());
85         }
86     }
87     else
88     {
89         if (infoErrors.size() >= ERROR_INFO_CAP)
90         {
91             erase(infoErrors.front());
92         }
93     }
94     constexpr const auto transactionIdVar = "TRANSACTION_ID";
95     // Length of 'TRANSACTION_ID' string.
96     constexpr const auto transactionIdVarSize = std::strlen(transactionIdVar);
97     // Length of 'TRANSACTION_ID=' string.
98     constexpr const auto transactionIdVarOffset = transactionIdVarSize + 1;
99 
100     // Flush all the pending log messages into the journal
101     journalSync();
102 
103     sd_journal* j = nullptr;
104     int rc = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY);
105     if (rc < 0)
106     {
107         logging::log<logging::level::ERR>(
108             "Failed to open journal",
109             logging::entry("DESCRIPTION=%s", strerror(-rc)));
110         return;
111     }
112 
113     std::string transactionIdStr = std::to_string(transactionId);
114     std::set<std::string> metalist;
115     auto metamap = g_errMetaMap.find(errMsg);
116     if (metamap != g_errMetaMap.end())
117     {
118         metalist.insert(metamap->second.begin(), metamap->second.end());
119     }
120 
121     // Add _PID field information in AdditionalData.
122     metalist.insert("_PID");
123 
124     std::vector<std::string> additionalData;
125 
126     // Read the journal from the end to get the most recent entry first.
127     // The result from the sd_journal_get_data() is of the form 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, (const void**)&data,
135                                  &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 NULL
144         // terminated strings, so need to specify the size to use to compare,
145         // use the returned length instead of anything that relies on NULL
146         // terminators like strlen().
147         // The data variable is in the form of 'TRANSACTION_ID=1234'. Remove
148         // the TRANSACTION_ID characters plus the (=) sign to do the comparison.
149         // 'data + transactionIdVarOffset' will be in the form of '1234'.
150         // 'length - transactionIdVarOffset' will be the length of '1234'.
151         if ((length <= (transactionIdVarOffset)) ||
152             (transactionIdStr.compare(0, transactionIdStr.size(),
153                                       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 variable.
169                 i++;
170                 continue;
171             }
172 
173             // Metadata variable found, save it and remove it from the set.
174             additionalData.emplace_back(data, length);
175             i = metalist.erase(i);
176         }
177         if (metalist.empty())
178         {
179             // All metadata variables found, break out of journal loop.
180             break;
181         }
182     }
183     if (!metalist.empty())
184     {
185         // Not all the metadata variables were found in the journal.
186         for (auto& metaVarStr : metalist)
187         {
188             logging::log<logging::level::INFO>(
189                 "Failed to find metadata",
190                 logging::entry("META_FIELD=%s", metaVarStr.c_str()));
191         }
192     }
193 
194     sd_journal_close(j);
195 
196     // Create error Entry dbus object
197     entryId++;
198     if (errLvl >= Entry::sevLowerLimit)
199     {
200         infoErrors.push_back(entryId);
201     }
202     else
203     {
204         realErrors.push_back(entryId);
205     }
206     auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
207                   std::chrono::system_clock::now().time_since_epoch())
208                   .count();
209     auto objPath = std::string(OBJ_ENTRY) + '/' + std::to_string(entryId);
210 
211     AssociationList objects{};
212     processMetadata(errMsg, additionalData, objects);
213 
214     auto e = std::make_unique<Entry>(busLog, objPath, entryId,
215                                      ms, // Milliseconds since 1970
216                                      errLvl, std::move(errMsg),
217                                      std::move(additionalData),
218                                      std::move(objects), fwVersion, *this);
219     serialize(*e);
220     entries.insert(std::make_pair(entryId, std::move(e)));
221 }
222 
223 void Manager::processMetadata(const std::string& errorName,
224                               const std::vector<std::string>& additionalData,
225                               AssociationList& objects) const
226 {
227     // additionalData is a list of "metadata=value"
228     constexpr auto separator = '=';
229     for (const auto& entryItem : additionalData)
230     {
231         auto found = entryItem.find(separator);
232         if (std::string::npos != found)
233         {
234             auto metadata = entryItem.substr(0, found);
235             auto iter = meta.find(metadata);
236             if (meta.end() != iter)
237             {
238                 (iter->second)(metadata, additionalData, objects);
239             }
240         }
241     }
242 }
243 
244 void Manager::erase(uint32_t entryId)
245 {
246     auto entryFound = entries.find(entryId);
247     if (entries.end() != entryFound)
248     {
249         // Delete the persistent representation of this error.
250         fs::path errorPath(ERRLOG_PERSIST_PATH);
251         errorPath /= std::to_string(entryId);
252         fs::remove(errorPath);
253 
254         auto removeId = [](std::list<uint32_t>& ids, uint32_t id) {
255             auto it = std::find(ids.begin(), ids.end(), id);
256             if (it != ids.end())
257             {
258                 ids.erase(it);
259             }
260         };
261         if (entryFound->second->severity() >= Entry::sevLowerLimit)
262         {
263             removeId(infoErrors, entryId);
264         }
265         else
266         {
267             removeId(realErrors, entryId);
268         }
269         entries.erase(entryFound);
270     }
271     else
272     {
273         logging::log<level::ERR>("Invalid entry ID to delete",
274                                  logging::entry("ID=%d", entryId));
275     }
276 }
277 
278 void Manager::restore()
279 {
280     auto sanity = [](const auto& id, const auto& restoredId) {
281         return id == restoredId;
282     };
283     std::vector<uint32_t> errorIds;
284 
285     fs::path dir(ERRLOG_PERSIST_PATH);
286     if (!fs::exists(dir) || fs::is_empty(dir))
287     {
288         return;
289     }
290 
291     for (auto& file : fs::directory_iterator(dir))
292     {
293         auto id = file.path().filename().c_str();
294         auto idNum = std::stol(id);
295         auto e = std::make_unique<Entry>(
296             busLog, std::string(OBJ_ENTRY) + '/' + id, idNum, *this);
297         if (deserialize(file.path(), *e))
298         {
299             // validate the restored error entry id
300             if (sanity(static_cast<uint32_t>(idNum), e->id()))
301             {
302                 e->emit_object_added();
303                 if (e->severity() >= Entry::sevLowerLimit)
304                 {
305                     infoErrors.push_back(idNum);
306                 }
307                 else
308                 {
309                     realErrors.push_back(idNum);
310                 }
311 
312                 entries.insert(std::make_pair(idNum, std::move(e)));
313                 errorIds.push_back(idNum);
314             }
315             else
316             {
317                 logging::log<logging::level::ERR>(
318                     "Failed in sanity check while restoring error entry. "
319                     "Ignoring error entry",
320                     logging::entry("ID_NUM=%d", idNum),
321                     logging::entry("ENTRY_ID=%d", e->id()));
322             }
323         }
324     }
325 
326     if (!errorIds.empty())
327     {
328         entryId = *(std::max_element(errorIds.begin(), errorIds.end()));
329     }
330 }
331 
332 void Manager::journalSync()
333 {
334     bool syncRequested = false;
335     auto fd = -1;
336     auto rc = -1;
337     auto wd = -1;
338     auto bus = sdbusplus::bus::new_default();
339 
340     auto start =
341         duration_cast<microseconds>(steady_clock::now().time_since_epoch())
342             .count();
343 
344     constexpr auto maxRetry = 2;
345     for (int i = 0; i < maxRetry; i++)
346     {
347         // Read timestamp from synced file
348         constexpr auto syncedPath = "/run/systemd/journal/synced";
349         std::ifstream syncedFile(syncedPath);
350         if (syncedFile.fail())
351         {
352             // If the synced file doesn't exist, a sync request will create it.
353             if (errno != ENOENT)
354             {
355                 log<level::ERR>("Failed to open journal synced file",
356                                 entry("FILENAME=%s", syncedPath),
357                                 entry("ERRNO=%d", errno));
358                 return;
359             }
360         }
361         else
362         {
363             // Only read the synced file if it exists.
364             // See if a sync happened by now
365             std::string timestampStr;
366             std::getline(syncedFile, timestampStr);
367             auto timestamp = std::stoll(timestampStr);
368             if (timestamp >= start)
369             {
370                 return;
371             }
372         }
373 
374         // Let's ask for a sync, but only once
375         if (!syncRequested)
376         {
377             syncRequested = true;
378 
379             constexpr auto JOURNAL_UNIT = "systemd-journald.service";
380             auto signal = SIGRTMIN + 1;
381 
382             auto method = bus.new_method_call(SYSTEMD_BUSNAME, SYSTEMD_PATH,
383                                               SYSTEMD_INTERFACE, "KillUnit");
384             method.append(JOURNAL_UNIT, "main", signal);
385             bus.call(method);
386             if (method.is_method_error())
387             {
388                 log<level::ERR>("Failed to kill journal service");
389                 return;
390             }
391             continue;
392         }
393 
394         // Let's install the inotify watch, if we didn't do that yet. This watch
395         // monitors the syncedFile for when journald updates it with a newer
396         // timestamp. This means the journal has been flushed.
397         if (fd < 0)
398         {
399             fd = inotify_init1(IN_NONBLOCK | IN_CLOEXEC);
400             if (fd < 0)
401             {
402                 log<level::ERR>("Failed to create inotify watch",
403                                 entry("ERRNO=%d", errno));
404                 return;
405             }
406 
407             constexpr auto JOURNAL_RUN_PATH = "/run/systemd/journal";
408             wd = inotify_add_watch(fd, JOURNAL_RUN_PATH,
409                                    IN_MOVED_TO | IN_DONT_FOLLOW | IN_ONLYDIR);
410             if (wd < 0)
411             {
412                 log<level::ERR>("Failed to watch journal directory",
413                                 entry("PATH=%s", JOURNAL_RUN_PATH),
414                                 entry("ERRNO=%d", errno));
415                 close(fd);
416                 return;
417             }
418             continue;
419         }
420 
421         // Let's wait until inotify reports an event
422         struct pollfd fds = {
423             .fd = fd,
424             .events = POLLIN,
425         };
426         constexpr auto pollTimeout = 5; // 5 seconds
427         rc = poll(&fds, 1, pollTimeout * 1000);
428         if (rc < 0)
429         {
430             log<level::ERR>("Failed to add event", entry("ERRNO=%d", errno),
431                             entry("ERR=%s", strerror(-rc)));
432             inotify_rm_watch(fd, wd);
433             close(fd);
434             return;
435         }
436         else if (rc == 0)
437         {
438             log<level::INFO>("Poll timeout, no new journal synced data",
439                              entry("TIMEOUT=%d", pollTimeout));
440             break;
441         }
442 
443         // Read from the specified file descriptor until there is no new data,
444         // throwing away everything read since the timestamp will be read at the
445         // beginning of the loop.
446         constexpr auto maxBytes = 64;
447         uint8_t buffer[maxBytes];
448         while (read(fd, buffer, maxBytes) > 0)
449             ;
450     }
451 
452     if (fd != -1)
453     {
454         if (wd != -1)
455         {
456             inotify_rm_watch(fd, wd);
457         }
458         close(fd);
459     }
460 
461     return;
462 }
463 
464 std::string Manager::readFWVersion()
465 {
466     std::string version;
467     std::ifstream versionFile{BMC_VERSION_FILE};
468     std::string line;
469     static constexpr auto VERSION_ID = "VERSION_ID=";
470 
471     while (std::getline(versionFile, line))
472     {
473         if (line.find(VERSION_ID) != std::string::npos)
474         {
475             auto pos = line.find_first_of('"') + 1;
476             version = line.substr(pos, line.find_last_of('"') - pos);
477             break;
478         }
479     }
480 
481     if (version.empty())
482     {
483         log<level::ERR>("Unable to read BMC firmware version");
484     }
485 
486     return version;
487 }
488 
489 } // namespace internal
490 } // namespace logging
491 } // namespace phosphor
492