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