From 5f4247f05d528345c56ca64a97d3ba571f26611d Mon Sep 17 00:00:00 2001 From: Adriana Kobylak Date: Thu, 15 Mar 2018 10:27:05 -0500 Subject: log_manager: Create journal sync function The Synchronize D-Bus method was a systemd patch that calls "journalctl --sync" and will not be upstreamed to systemd. Instead duplicate the function locally in the log_manager so that the patch can be dropped, since the systemd journal service would not start on time if it was idle, leading to missing metadata. Closes openbmc/openbmc#2257 Tested: While printing continously into the journal, verify that a commit request is blocked until the journal is flushed. Change-Id: I8248c4c2e2eaeb041f7876832b395b053409acdd Signed-off-by: Adriana Kobylak --- log_manager.cpp | 142 ++++++++++++++++++++++++++++++++++++++++++++++++++++---- log_manager.hpp | 6 +++ 2 files changed, 139 insertions(+), 9 deletions(-) diff --git a/log_manager.cpp b/log_manager.cpp index 92454fe..6717a7a 100644 --- a/log_manager.cpp +++ b/log_manager.cpp @@ -1,13 +1,17 @@ #include +#include #include #include #include +#include #include #include #include #include +#include #include #include +#include #include "config.h" #include "elog_entry.hpp" #include @@ -16,6 +20,7 @@ #include "elog_serialize.hpp" using namespace phosphor::logging; +using namespace std::chrono; extern const std::map> meta; @@ -25,7 +30,6 @@ namespace logging { namespace internal { - inline auto getLevel(const std::string& errMsg) { auto reqLevel = Entry::Level::Error; // Default to Error @@ -75,14 +79,8 @@ void Manager::_commit(uint64_t transactionId, std::string&& errMsg, // Length of 'TRANSACTION_ID=' string. constexpr const auto transactionIdVarOffset = transactionIdVarSize + 1; - // Flush all the pending log messages into the journal via Synchronize - constexpr auto JOURNAL_BUSNAME = "org.freedesktop.journal1"; - constexpr auto JOURNAL_PATH = "/org/freedesktop/journal1"; - constexpr auto JOURNAL_INTERFACE = "org.freedesktop.journal1"; - auto bus = sdbusplus::bus::new_default(); - auto method = bus.new_method_call(JOURNAL_BUSNAME, JOURNAL_PATH, - JOURNAL_INTERFACE, "Synchronize"); - bus.call_noreply(method); + // Flush all the pending log messages into the journal + journalSync(); sd_journal *j = nullptr; int rc = sd_journal_open(&j, SD_JOURNAL_LOCAL_ONLY); @@ -322,6 +320,132 @@ void Manager::restore() } } +void Manager::journalSync() +{ + bool syncRequested = false; + auto fd = -1; + auto rc = -1; + auto wd = -1; + auto bus = sdbusplus::bus::new_default(); + + auto start = + duration_cast(steady_clock::now().time_since_epoch()) + .count(); + + constexpr auto maxRetry = 2; + for (int i = 0; i < maxRetry; i++) + { + // Read timestamp from synced file + constexpr auto syncedPath = "/run/systemd/journal/synced"; + std::ifstream syncedFile(syncedPath); + if (syncedFile.fail()) + { + log("Failed to open journal synced file", + entry("FILENAME=%s", syncedPath), + entry("ERRNO=%d", errno)); + return; + } + + // See if a sync happened by now + std::string timestampStr; + std::getline(syncedFile, timestampStr); + auto timestamp = stoll(timestampStr); + if (timestamp >= start) + { + return; + } + + // Let's ask for a sync, but only once + if (!syncRequested) + { + syncRequested = true; + + constexpr auto SYSTEMD_BUSNAME = "org.freedesktop.systemd1"; + constexpr auto SYSTEMD_PATH = "/org/freedesktop/systemd1"; + constexpr auto SYSTEMD_INTERFACE = + "org.freedesktop.systemd1.Manager"; + constexpr auto JOURNAL_UNIT = "systemd-journald.service"; + auto signal = SIGRTMIN + 1; + + auto method = bus.new_method_call(SYSTEMD_BUSNAME, SYSTEMD_PATH, + SYSTEMD_INTERFACE, "KillUnit"); + method.append(JOURNAL_UNIT, "main", signal); + bus.call(method); + if (method.is_method_error()) + { + log("Failed to kill journal service"); + return; + } + continue; + } + + // Let's install the inotify watch, if we didn't do that yet. This watch + // monitors the syncedFile for when journald updates it with a newer + // timestamp. This means the journal has been flushed. + if (fd < 0) + { + fd = inotify_init1(IN_NONBLOCK | IN_CLOEXEC); + if (fd < 0) + { + log("Failed to create inotify watch", + entry("ERRNO=%d", errno)); + return; + } + + constexpr auto JOURNAL_RUN_PATH = "/run/systemd/journal"; + wd = inotify_add_watch(fd, JOURNAL_RUN_PATH, + IN_MOVED_TO | IN_DONT_FOLLOW | IN_ONLYDIR); + if (wd < 0) + { + log("Failed to watch journal directory", + entry("PATH=%s", JOURNAL_RUN_PATH), + entry("ERRNO=%d", errno)); + close(fd); + return; + } + continue; + } + + // Let's wait until inotify reports an event + struct pollfd fds = { + .fd = fd, + .events = POLLIN, + }; + constexpr auto pollTimeout = 5; // 5 seconds + rc = poll(&fds, 1, pollTimeout * 1000); + if (rc < 0) + { + log("Failed to add event", entry("ERRNO=%d", errno), + entry("ERR=%s", strerror(-rc))); + inotify_rm_watch(fd, wd); + close(fd); + return; + } + else if (rc == 0) + { + log("Poll timeout, no new journal synced data", + entry("TIMEOUT=%d", pollTimeout)); + break; + } + + // Read from the specified file descriptor until there is no new data, + // throwing away everything read since the timestamp will be read at the + // beginning of the loop. + constexpr auto maxBytes = 64; + uint8_t buffer[maxBytes]; + while (read(fd, buffer, maxBytes) > 0) + ; + } + + if ((fd != -1) && (wd != -1)) + { + inotify_rm_watch(fd, wd); + close(fd); + } + + return; +} + } // namespace internal } // namespace logging } // namepsace phosphor diff --git a/log_manager.hpp b/log_manager.hpp index 9339a6f..d62a25e 100644 --- a/log_manager.hpp +++ b/log_manager.hpp @@ -130,6 +130,12 @@ class Manager : public details::ServerObject const std::vector& additionalData, AssociationList& objects) const; + /** @brief Synchronize unwritten journal messages to disk. + * @details This is the same implementation as the systemd command + * "journalctl --sync". + */ + void journalSync(); + /** @brief Persistent sdbusplus DBus bus connection. */ sdbusplus::bus::bus& busLog; -- cgit v1.2.1