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