regulators: Enhance SystemdJournal::getMessages()
Enhance the SystemdJournal::getMessages() method that obtains systemd
journal entries with a specified field value:
* Handle journal entries that do not have expected fields. All journal
fields are optional, so if a field is missing this is not an error
condition.
* Use built-in filtering support provided by the systemd journal API.
This will likely provide better performance.
* Use C++ std::string methods to perform field data parsing.
* Add short sleep before acquiring journal messages. Otherwise recently
added messages are sometimes not available.
Tested:
* Tested where journal entry is missing expected fields.
* Tested that built-in filtering support results in the desired set of
journal entries.
* Tested field data parsing. Tested where value has expected format and
when it does not.
* Verified all journal entries, including the most recently added ones,
are obtained.
* Tested error handling when each sd_journal_*() function fails.
* For complete test plan, see
https://gist.github.com/smccarney/bd4e546a76ee05e4df939eb69e23daee
Signed-off-by: Shawn McCarney <shawnmm@us.ibm.com>
Change-Id: I066492edc05691b240d768c5b99cfa6f07d83ddf
diff --git a/phosphor-regulators/src/journal.cpp b/phosphor-regulators/src/journal.cpp
index be94275..ba9d846 100644
--- a/phosphor-regulators/src/journal.cpp
+++ b/phosphor-regulators/src/journal.cpp
@@ -1,4 +1,3 @@
-
/**
* Copyright © 2020 IBM Corporation
*
@@ -17,21 +16,27 @@
#include "journal.hpp"
+#include <errno.h>
+#include <stdint.h>
#include <string.h>
#include <time.h>
-#include <cstdint>
-#include <ctime>
+#include <chrono>
#include <stdexcept>
-
-using namespace phosphor::logging;
+#include <thread>
namespace phosphor::power::regulators
{
+/**
+ * @class JournalCloser
+ *
+ * Automatically closes the journal when the object goes out of scope.
+ */
class JournalCloser
{
public:
+ // Specify which compiler-generated methods we want
JournalCloser() = delete;
JournalCloser(const JournalCloser&) = delete;
JournalCloser(JournalCloser&&) = delete;
@@ -41,6 +46,7 @@
JournalCloser(sd_journal* journal) : journal{journal}
{
}
+
~JournalCloser()
{
sd_journal_close(journal);
@@ -50,45 +56,16 @@
sd_journal* journal{nullptr};
};
-std::string SystemdJournal::getFieldValue(sd_journal* journal,
- const char* field) const
-{
- const char* data{nullptr};
- size_t length{0};
-
- // Get field data
- int rc = sd_journal_get_data(journal, field, (const void**)&data, &length);
- if (rc < 0)
- {
- throw std::runtime_error{
- std::string{"Failed to read journal entry field: "} +
- strerror(-rc)};
- }
-
- // Get field value
- size_t prefix{0};
- const void* eq = memchr(data, '=', length);
- if (eq)
- {
- prefix = (const char*)eq - data + 1;
- }
- else
- {
- prefix = 0;
- }
-
- std::string value{data + prefix, length - prefix};
-
- return value;
-}
-
std::vector<std::string>
SystemdJournal::getMessages(const std::string& field,
const std::string& fieldValue, unsigned int max)
{
- sd_journal* journal;
- std::vector<std::string> messages;
+ // Sleep 100ms; otherwise recent journal entries sometimes not available
+ using namespace std::chrono_literals;
+ std::this_thread::sleep_for(100ms);
+ // Open the journal
+ sd_journal* journal;
int rc = sd_journal_open(&journal, SD_JOURNAL_LOCAL_ONLY);
if (rc < 0)
{
@@ -96,48 +73,35 @@
strerror(-rc)};
}
+ // Create object to automatically close journal
JournalCloser closer{journal};
+ // Add match so we only loop over entries with specified field value
+ std::string match{field + '=' + fieldValue};
+ rc = sd_journal_add_match(journal, match.c_str(), 0);
+ if (rc < 0)
+ {
+ throw std::runtime_error{std::string{"Failed to add journal match: "} +
+ strerror(-rc)};
+ }
+
+ // Loop through matching entries from newest to oldest
+ std::vector<std::string> messages;
+ messages.reserve((max != 0) ? max : 10);
+ std::string syslogID, pid, message, timeStamp, line;
SD_JOURNAL_FOREACH_BACKWARDS(journal)
{
- // Get input field
- std::string value = getFieldValue(journal, field.c_str());
+ // Get relevant journal entry fields
+ timeStamp = getTimeStamp(journal);
+ syslogID = getFieldValue(journal, "SYSLOG_IDENTIFIER");
+ pid = getFieldValue(journal, "_PID");
+ message = getFieldValue(journal, "MESSAGE");
- // Compare field value and read data
- if (value == fieldValue)
- {
- // Get SYSLOG_IDENTIFIER field
- std::string syslog = getFieldValue(journal, "SYSLOG_IDENTIFIER");
+ // Build one line string containing field values
+ line = timeStamp + " " + syslogID + "[" + pid + "]: " + message;
+ messages.emplace(messages.begin(), line);
- // Get _PID field
- std::string pid = getFieldValue(journal, "_PID");
-
- // Get MESSAGE field
- std::string message = getFieldValue(journal, "MESSAGE");
-
- // Get realtime
- uint64_t usec{0};
- rc = sd_journal_get_realtime_usec(journal, &usec);
- if (rc < 0)
- {
- throw std::runtime_error{
- std::string{"Failed to get journal entry timestamp: "} +
- strerror(-rc)};
- }
-
- // Convert realtime microseconds to date format
- char dateBuffer[80];
- std::string date;
- std::time_t timeInSecs = usec / 1000000;
- strftime(dateBuffer, sizeof(dateBuffer), "%b %d %H:%M:%S",
- std::localtime(&timeInSecs));
- date = dateBuffer;
-
- // Store value to messages
- value = date + " " + syslog + "[" + pid + "]: " + message;
- messages.insert(messages.begin(), value);
- }
- // Set the maximum number of messages
+ // Stop looping if a max was specified and we have reached it
if ((max != 0) && (messages.size() >= max))
{
break;
@@ -147,4 +111,71 @@
return messages;
}
-} // namespace phosphor::power::regulators
\ No newline at end of file
+std::string SystemdJournal::getFieldValue(sd_journal* journal,
+ const std::string& field)
+{
+ std::string value{};
+
+ // Get field data from current journal entry
+ const void* data{nullptr};
+ size_t length{0};
+ int rc = sd_journal_get_data(journal, field.c_str(), &data, &length);
+ if (rc < 0)
+ {
+ if (-rc == ENOENT)
+ {
+ // Current entry does not include this field; return empty value
+ return value;
+ }
+ else
+ {
+ throw std::runtime_error{
+ std::string{"Failed to read journal entry field: "} +
+ strerror(-rc)};
+ }
+ }
+
+ // Get value from field data. Field data in format "FIELD=value".
+ std::string dataString{static_cast<const char*>(data), length};
+ std::string::size_type pos = dataString.find('=');
+ if ((pos != std::string::npos) && ((pos + 1) < dataString.size()))
+ {
+ // Value is substring after the '='
+ value = dataString.substr(pos + 1);
+ }
+
+ return value;
+}
+
+std::string SystemdJournal::getTimeStamp(sd_journal* journal)
+{
+ // Get realtime (wallclock) timestamp of current journal entry. The
+ // timestamp is in microseconds since the epoch.
+ uint64_t usec{0};
+ int rc = sd_journal_get_realtime_usec(journal, &usec);
+ if (rc < 0)
+ {
+ throw std::runtime_error{
+ std::string{"Failed to get journal entry timestamp: "} +
+ strerror(-rc)};
+ }
+
+ // Convert to number of seconds since the epoch
+ time_t secs = usec / 1000000;
+
+ // Convert seconds to tm struct required by strftime()
+ struct tm* timeStruct = localtime(&secs);
+ if (timeStruct == nullptr)
+ {
+ throw std::runtime_error{
+ std::string{"Invalid journal entry timestamp: "} + strerror(errno)};
+ }
+
+ // Convert tm struct into a date/time string
+ char timeStamp[80];
+ strftime(timeStamp, sizeof(timeStamp), "%b %d %H:%M:%S", timeStruct);
+
+ return timeStamp;
+}
+
+} // namespace phosphor::power::regulators
diff --git a/phosphor-regulators/src/journal.hpp b/phosphor-regulators/src/journal.hpp
index 4499aa6..2199c8c 100644
--- a/phosphor-regulators/src/journal.hpp
+++ b/phosphor-regulators/src/journal.hpp
@@ -44,6 +44,22 @@
virtual ~Journal() = default;
/**
+ * Gets the journal messages that have the specified field set to the
+ * specified value.
+ *
+ * The messages in the returned vector are ordered from oldest to newest.
+ *
+ * @param field journal field name
+ * @param fieldValue expected field value
+ * @param max Maximum number of messages to return. Specify 0 to return all
+ * matching messages.
+ * @return matching messages from the journal
+ */
+ virtual std::vector<std::string> getMessages(const std::string& field,
+ const std::string& fieldValue,
+ unsigned int max = 0) = 0;
+
+ /**
* Logs a debug message in the system journal.
*
* @param message message to log
@@ -84,21 +100,6 @@
* @param messages messages to log
*/
virtual void logInfo(const std::vector<std::string>& messages) = 0;
-
- /**
- * Gets the journal messages that have the specified field set to the
- * specified value.
- *
- * @param field journal field to use during search
- * @param fieldValue expected field value
- * @param max Maximum number of messages to return.
- * Specify 0 to return all matching messages.
- *
- * @return matching messages from the journal
- */
- virtual std::vector<std::string> getMessages(const std::string& field,
- const std::string& fieldValue,
- unsigned int max = 0) = 0;
};
/**
@@ -172,13 +173,24 @@
private:
/**
- * Gets the data object associated with a specific field from the
- * current journal entry and return the data as string.
+ * Gets the value of the specified field for the current journal entry.
*
- * @param journal the current journal entry
- * @param field journal field to use during search
+ * Returns an empty string if the current journal entry does not have the
+ * specified field.
+ *
+ * @param journal current journal entry
+ * @param field journal field name
+ * @return field value
*/
- std::string getFieldValue(sd_journal* journal, const char* field) const;
+ std::string getFieldValue(sd_journal* journal, const std::string& field);
+
+ /**
+ * Gets the realtime (wallclock) timestamp for the current journal entry.
+ *
+ * @param journal current journal entry
+ * @return timestamp as a date/time string
+ */
+ std::string getTimeStamp(sd_journal* journal);
};
} // namespace phosphor::power::regulators