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 <anoo@us.ibm.com>
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 <fstream>
+#include <future>
#include <iostream>
#include <chrono>
#include <cstdio>
+#include <poll.h>
#include <set>
#include <string>
#include <vector>
#include <sdbusplus/vtable.hpp>
+#include <sys/inotify.h>
#include <systemd/sd-bus.h>
#include <systemd/sd-journal.h>
+#include <unistd.h>
#include "config.h"
#include "elog_entry.hpp"
#include <phosphor-logging/log.hpp>
@@ -16,6 +20,7 @@
#include "elog_serialize.hpp"
using namespace phosphor::logging;
+using namespace std::chrono;
extern const std::map<metadata::Metadata,
std::function<metadata::associations::Type>> meta;
@@ -25,7 +30,6 @@
{
namespace internal
{
-
inline auto getLevel(const std::string& errMsg)
{
auto reqLevel = Entry::Level::Error; // Default to Error
@@ -75,14 +79,8 @@
// 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::journalSync()
+{
+ bool syncRequested = false;
+ auto fd = -1;
+ auto rc = -1;
+ auto wd = -1;
+ auto bus = sdbusplus::bus::new_default();
+
+ auto start =
+ duration_cast<microseconds>(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<level::ERR>("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<level::ERR>("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<level::ERR>("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<level::ERR>("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<level::ERR>("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<level::INFO>("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