logger: Fixes to allow plugins access to hostIDs (#3197)

include/osquery/core.h

@@ -203,3 +203,28 @@ using RecursiveMutex = std::recursive_mutex;
 /// Helper alias for write locking a recursive mutex.
 using RecursiveLock = std::lock_guard<std::recursive_mutex>;
 }
+
+/**
+ * @brief An abstract similar to boost's noncopyable that defines moves.
+ *
+ * By defining protected move constructors we allow the children to assign
+ * their's as default.
+ */
+class only_movable {
+ protected:
+  /// Boilerplate self default constructor.
+  only_movable() {}
+
+  /// Boilerplate self destructor.
+  ~only_movable() {}
+
+  /// Important, existence of a move constructor.
+  only_movable(only_movable&&) {}
+
+ private:
+  /// Important, a private copy constructor prevents copying.
+  only_movable(const only_movable&);
+
+  /// Important, a private copy assignment constructor prevents copying.
+  only_movable& operator=(const only_movable&);
+};

include/osquery/logger.h

@@ -22,6 +22,7 @@
 
 #include <boost/noncopyable.hpp>
 
+#include <osquery/core.h>
 #include <osquery/database.h>
 #include <osquery/flags.h>
 #include <osquery/registry.h>
@@ -44,20 +45,32 @@ enum StatusLogSeverity {
 /// An intermediate status log line.
 struct StatusLogLine {
  public:
-  /// An integer severity level mimicing Glog's.
+  /// An integer severity level mimicking Glog's.
   StatusLogSeverity severity;
+
   /// The name of the file emitting the status log.
   std::string filename;
+
   /// The line of the file emitting the status log.
-  int line;
+  size_t line;
+
   /// The string-formatted status message.
   std::string message;
-  /// The host identifier
-  std::string identifier;
+
   /// The ASCII time stamp for when the status message was emitted
   std::string calendar_time;
+
   /// The UNIX time for when the status message was emitted
   size_t time;
+
+  /**
+   * @brief The host identifier at the time when logs are flushed.
+   *
+   * There is occasionally a delay between logging a status and decorating
+   * with the host identifier. In most cases the identifier is static so this
+   * does not matter. In some cases the host identifier causes database lookups.
+   */
+  std::string identifier;
 };
 
 /**

include/osquery/tables.h

@@ -57,31 +57,6 @@
 
 namespace osquery {
 
-/**
- * @brief An abstract similar to boost's noncopyable that defines moves.
- *
- * By defining protected move constructors we allow the children to assign
- * their's as default.
- */
-class only_movable {
- protected:
-  /// Boilerplate self default constructor.
-  only_movable() {}
-
-  /// Boilerplate self destructor.
-  ~only_movable() {}
-
-  /// Important, existance of a move constructor.
-  only_movable(only_movable&&) {}
-
- private:
-  /// Important, a private copy constructor prevents copying.
-  only_movable(const only_movable&);
-
-  /// Important, a private copy assignment constructor prevents copying.
-  only_movable& operator=(const only_movable&);
-};
-
 /**
  * @brief osquery does not yet use a NULL type.
  *

osquery/core/system.cpp

@@ -103,6 +103,7 @@ std::string getHostname() {
   static long max_hostname = sysconf(_SC_HOST_NAME_MAX);
   long size = (max_hostname > 255) ? max_hostname + 1 : 256;
 #endif
+
   char* hostname = (char*)malloc(size);
   std::string hostname_string;
   if (hostname != nullptr) {
@@ -154,7 +155,6 @@ std::string generateHostUUID() {
   }
 
   // Unable to get the hardware UUID, just return a new UUID
-  VLOG(1) << "Cannot retrieve platform UUID: generating an ephemeral UUID";
   return generateNewUUID();
 }
 
@@ -165,7 +165,6 @@ Status getInstanceUUID(std::string& ident) {
   if (ident.size() == 0) {
     // There was no UUID stored in the database, generate one and store it.
     ident = osquery::generateNewUUID();
-    VLOG(1) << "Using UUID " << ident << " as host identifier";
     return setDatabaseValue(kPersistentSettings, "instance_uuid_v1", ident);
   }
 
@@ -176,8 +175,6 @@ Status getEphemeralUUID(std::string& ident) {
   if (ident.size() == 0) {
     ident = osquery::generateNewUUID();
   }
-  VLOG(1) << "Using UUID " << ident << " as host identifier";
-
   return Status(0, "OK");
 }
 
@@ -187,10 +184,8 @@ Status getHostUUID(std::string& ident) {
   if (ident.size() == 0) {
     // There was no UUID stored in the database, generate one and store it.
     ident = osquery::generateHostUUID();
-    VLOG(1) << "Using UUID " << ident << " as host identifier";
     return setDatabaseValue(kPersistentSettings, "host_uuid_v3", ident);
   }
-
   return status;
 }
 
@@ -207,6 +202,7 @@ std::string getHostIdentifier() {
 
   Status result(2);
   if (ident.size() == 0) {
+    // The identifier has not been set yet.
     if (FLAGS_host_identifier == "uuid") {
       result = getHostUUID(ident);
     } else if (FLAGS_host_identifier == "instance") {
@@ -218,13 +214,13 @@ std::string getHostIdentifier() {
     }
 
     if (!result.ok()) {
-      // https://github.com/facebook/osquery/issues/3174
-
       // assuming the default of "hostname" as the machine identifier
       // intentionally not set to `ident` because the hostname may change
       // throughout the life of the process and we always want to be using the
       // most current hostname
       return osquery::getHostname();
+    } else {
+      VLOG(1) << "Using host identifier: " << ident;
     }
   }
   return ident;

osquery/logger/logger.cpp

@@ -296,11 +296,11 @@ static void deserializeIntermediateLog(const PluginRequest& request,
     log.push_back({
         (StatusLogSeverity)item.second.get<int>("s", O_INFO),
         item.second.get<std::string>("f", "<unknown>"),
-        item.second.get<int>("i", 0),
+        item.second.get<size_t>("i", 0),
         item.second.get<std::string>("m", ""),
-        item.second.get<std::string>("h", ""),
         item.second.get<std::string>("c", ""),
         item.second.get<size_t>("u", 0),
+        item.second.get<std::string>("h", ""),
     });
   }
 }
@@ -446,15 +446,17 @@ void BufferedLogSink::send(google::LogSeverity severity,
                            const struct ::tm* tm_time,
                            const char* message,
                            size_t message_len) {
+  // WARNING, be extremely careful when accessing data here.
+  // This should not cause any persistent storage or logging actions.
   {
     WriteLock lock(kBufferedLogSinkLogs);
     logs_.push_back({(StatusLogSeverity)severity,
                      std::string(base_filename),
-                     line,
+                     static_cast<size_t>(line),
                      std::string(message, message_len),
-                     getHostIdentifier(),
                      toAsciiTimeUTC(tm_time),
-                     toUnixTime(tm_time)});
+                     toUnixTime(tm_time),
+                     std::string()});
   }
 
   // The daemon will relay according to the schedule.
@@ -604,12 +606,18 @@ void relayStatusLogs(bool async) {
   }
 
   auto sender = ([]() {
+    auto identifier = getHostIdentifier();
+
     // Construct a status log plugin request.
     PluginRequest request = {{"status", "true"}};
-
     {
       WriteLock lock(kBufferedLogSinkLogs);
       auto& status_logs = BufferedLogSink::dump();
+      for (auto& log : status_logs) {
+        // Copy the host identifier into each status log.
+        log.identifier = identifier;
+      }
+
       serializeIntermediateLog(status_logs, request);
       if (!request["log"].empty()) {
         request["log"].pop_back();

osquery/logger/plugins/filesystem.cpp

@@ -113,8 +113,9 @@ Status FilesystemLoggerPlugin::logStatus(
     const std::vector<StatusLogLine>& log) {
   for (const auto& item : log) {
     // Emit this intermediate log to the Glog filesystem logger.
-    google::LogMessage(
-        item.filename.c_str(), item.line, (google::LogSeverity)item.severity)
+    google::LogMessage(item.filename.c_str(),
+                       static_cast<int>(item.line),
+                       (google::LogSeverity)item.severity)
             .stream()
         << item.message;
   }

osquery/logger/plugins/tests/buffered_tests.cpp

@@ -39,7 +39,7 @@ MATCHER_P(MatchesStatus, expected, "") {
     pt::read_json(json_in, actual);
     return expected.severity == actual.get<int>("severity") &&
            expected.filename == actual.get<std::string>("filename") &&
-           expected.line == actual.get<int>("line") &&
+           expected.line == actual.get<size_t>("line") &&
            expected.message == actual.get<std::string>("message");
   } catch (const std::exception& e) {
     return false;

osquery/logger/tests/logger_tests.cpp

@@ -34,7 +34,7 @@ class LoggerTests : public testing::Test {
     log_lines.clear();
     status_messages.clear();
     statuses_logged = 0;
-    last_status = {O_INFO, "", -1, "", "host", "cal_time", 0};
+    last_status = {O_INFO, "", 10, "", "cal_time", 0, "host"};
   }
 
   void TearDown() override {
@@ -173,11 +173,19 @@ TEST_F(LoggerTests, test_log_string) {
 }
 
 TEST_F(LoggerTests, test_logger_log_status) {
+  std::string warning = "Logger test is generating a warning status (2)";
+  auto now = getUnixTime();
   // This will be printed to stdout.
-  LOG(WARNING) << "Logger test is generating a warning status (2)";
+  LOG(WARNING) << warning;
 
   // The second warning status will be sent to the logger plugin.
   EXPECT_EQ(1U, LoggerTests::statuses_logged);
+
+  EXPECT_EQ(O_WARNING, LoggerTests::last_status.severity);
+  EXPECT_GT(LoggerTests::last_status.line, 0U);
+  EXPECT_EQ(warning, LoggerTests::last_status.message);
+  EXPECT_GE(now, LoggerTests::last_status.time);
+  EXPECT_EQ(getHostIdentifier(), LoggerTests::last_status.identifier);
 }
 
 TEST_F(LoggerTests, test_logger_status_level) {