Improve logging tests, add filesystem logger tests

include/osquery/logger.h

@@ -103,7 +103,7 @@ struct StatusLogLine {
 class LoggerPlugin : public Plugin {
  public:
   /// The LoggerPlugin PluginRequest action router.
-  Status call(const PluginRequest& request, PluginResponse& response);
+  Status call(const PluginRequest& request, PluginResponse& response) override;
 
  protected:
   /** @brief Virtual method which should implement custom logging.

osquery/logger/CMakeLists.txt

@@ -9,11 +9,11 @@ ADD_OSQUERY_LIBRARY(FALSE osquery_logger_plugins
   plugins/syslog.cpp
 )
 
-# Kepp the logger testing in the additional to test filesystem logging.
+# Keep the logger testing in the additional to test filesystem logging.
 # There is a significant difference between the Glog-backed filesystem plugin
 # and other, which use a Glog sink. They must be tested in tandem.
 file(GLOB OSQUERY_LOGGER_TESTS "tests/*.cpp")
-ADD_OSQUERY_TEST(FALSE ${OSQUERY_LOGGER_TESTS})
+ADD_OSQUERY_TEST(TRUE ${OSQUERY_LOGGER_TESTS})
 
 file(GLOB OSQUERY_LOGGER_PLUGIN_TESTS "plugins/tests/*.cpp")
 ADD_OSQUERY_TEST(FALSE ${OSQUERY_LOGGER_PLUGIN_TESTS})

osquery/logger/logger.cpp

@@ -189,8 +189,7 @@ 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<std::string>("m", ""),
+        item.second.get<int>("i", 0), item.second.get<std::string>("m", ""),
     });
   }
 }
@@ -292,10 +291,8 @@ void BufferedLogSink::send(google::LogSeverity severity,
       if (std::find(enabled.begin(), enabled.end(), logger) != enabled.end()) {
         // May use the logs_ storage to buffer/delay sending logs.
         std::vector<StatusLogLine> log;
-        log.push_back({(StatusLogSeverity)severity,
-                       std::string(base_filename),
-                       line,
-                       std::string(message, message_len)});
+        log.push_back({(StatusLogSeverity)severity, std::string(base_filename),
+                       line, std::string(message, message_len)});
         PluginRequest request = {{"status", "true"}};
         serializeIntermediateLog(log, request);
         if (!request["log"].empty()) {
@@ -305,10 +302,8 @@ void BufferedLogSink::send(google::LogSeverity severity,
       }
     }
   } else {
-    logs_.push_back({(StatusLogSeverity)severity,
-                     std::string(base_filename),
-                     line,
-                     std::string(message, message_len)});
+    logs_.push_back({(StatusLogSeverity)severity, std::string(base_filename),
+                     line, std::string(message, message_len)});
   }
 }
 
@@ -340,9 +335,8 @@ Status logString(const std::string& message, const std::string& category) {
 Status logString(const std::string& message,
                  const std::string& category,
                  const std::string& receiver) {
-  auto status = Registry::call(
+  return Registry::call(
       "logger", receiver, {{"string", message}, {"category", category}});
-  return Status(0, "OK");
 }
 
 Status logQueryLogItem(const QueryLogItem& results) {

osquery/logger/plugins/filesystem.cpp

@@ -38,20 +38,33 @@ const std::string kFilesystemLoggerFilename = "osqueryd.results.log";
 const std::string kFilesystemLoggerSnapshots = "osqueryd.snapshots.log";
 const std::string kFilesystemLoggerHealth = "osqueryd.health.log";
 
-std::mutex filesystemLoggerPluginMutex;
+std::mutex kFilesystemLoggerPluginMutex;
 
 class FilesystemLoggerPlugin : public LoggerPlugin {
  public:
-  Status setUp();
-  Status logString(const std::string& s);
-  Status logStringToFile(const std::string& s, const std::string& filename);
-  Status logSnapshot(const std::string& s);
-  Status logHealth(const std::string& s);
-  Status init(const std::string& name, const std::vector<StatusLogLine>& log);
-  Status logStatus(const std::vector<StatusLogLine>& log);
+  Status setUp() override;
+
+  Status logString(const std::string& s) override;
+
+  Status logSnapshot(const std::string& s) override;
+
+  Status logHealth(const std::string& s) override;
+
+  Status init(const std::string& name,
+              const std::vector<StatusLogLine>& log) override;
+
+  Status logStatus(const std::vector<StatusLogLine>& log) override;
+
+ private:
+  Status logStringToFile(const std::string& s,
+                         const std::string& filename,
+                         bool empty = false);
 
  private:
   fs::path log_path_;
+
+ private:
+  FRIEND_TEST(FilesystemLoggerTests, test_filesystem_init);
 };
 
 REGISTER(FilesystemLoggerPlugin, "logger", "filesystem");
@@ -63,12 +76,7 @@ Status FilesystemLoggerPlugin::setUp() {
   FLAGS_logfile_mode = FLAGS_logger_mode;
 
   // Ensure that we create the results log here.
-  auto status = logString("");
-  if (!status.ok()) {
-    return status;
-  }
-
-  return Status(0, "OK");
+  return logStringToFile("", kFilesystemLoggerFilename, true);
 }
 
 Status FilesystemLoggerPlugin::logString(const std::string& s) {
@@ -76,11 +84,14 @@ Status FilesystemLoggerPlugin::logString(const std::string& s) {
 }
 
 Status FilesystemLoggerPlugin::logStringToFile(const std::string& s,
-                                               const std::string& filename) {
-  std::lock_guard<std::mutex> lock(filesystemLoggerPluginMutex);
+                                               const std::string& filename,
+                                               bool empty) {
+  std::lock_guard<std::mutex> lock(kFilesystemLoggerPluginMutex);
   try {
-    auto status = writeTextFile(
-        (log_path_ / filename).string(), s + '\n', FLAGS_logger_mode, true);
+    auto status = writeTextFile((log_path_ / filename).string(),
+                                (empty) ? "" : s + '\n',
+                                FLAGS_logger_mode,
+                                true);
     if (!status.ok()) {
       return status;
     }
@@ -94,9 +105,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).stream()
+    google::LogMessage(
+        item.filename.c_str(), item.line, (google::LogSeverity)item.severity)
+            .stream()
         << item.message;
   }
 

osquery/logger/plugins/syslog.cpp

@@ -22,9 +22,10 @@ FLAG(int32,
 
 class SyslogLoggerPlugin : public LoggerPlugin {
  public:
-  Status logString(const std::string& s);
-  Status init(const std::string& name, const std::vector<StatusLogLine>& log);
-  Status logStatus(const std::vector<StatusLogLine>& log);
+  Status logString(const std::string& s) override;
+  Status init(const std::string& name,
+              const std::vector<StatusLogLine>& log) override;
+  Status logStatus(const std::vector<StatusLogLine>& log) override;
 };
 
 REGISTER(SyslogLoggerPlugin, "logger", "syslog");

osquery/logger/plugins/tests/filesystem_logger_tests.cpp

@@ -0,0 +1,98 @@
+/*
+ *  Copyright (c) 2014-present, Facebook, Inc.
+ *  All rights reserved.
+ *
+ *  This source code is licensed under the BSD-style license found in the
+ *  LICENSE file in the root directory of this source tree. An additional grant
+ *  of patent rights can be found in the PATENTS file in the same directory.
+ *
+ */
+
+#include <gtest/gtest.h>
+
+#include <boost/filesystem/operations.hpp>
+
+#include <osquery/logger.h>
+
+#include "osquery/core/test_util.h"
+
+namespace fs = boost::filesystem;
+
+namespace osquery {
+
+DECLARE_string(logger_path);
+
+class FilesystemLoggerTests : public testing::Test {
+ public:
+  void SetUp() {
+    auto logger_path = fs::path(kTestWorkingDirectory) / "unittests.logs";
+    FLAGS_logger_path = logger_path.string();
+    fs::create_directories(FLAGS_logger_path);
+
+    // Set the expected results path.
+    results_path_ = (logger_path / "osqueryd.results.log").string();
+
+    // Backup the logging status, then disable.
+    logging_status_ = FLAGS_disable_logging;
+    FLAGS_disable_logging = false;
+  }
+
+  void TearDown() { FLAGS_disable_logging = logging_status_; }
+
+  std::string getContent() { return std::string(); }
+
+ protected:
+  /// Save the status of logging before running tests, restore afterward.
+  bool logging_status_{true};
+
+  /// Results log path.
+  std::string results_path_;
+};
+
+TEST_F(FilesystemLoggerTests, test_filesystem_init) {
+  EXPECT_TRUE(Registry::exists("logger", "filesystem"));
+
+  // This will attempt to log a string (an empty string).
+  EXPECT_TRUE(Registry::setActive("logger", "filesystem"));
+  EXPECT_TRUE(Registry::get("logger", "filesystem")->setUp());
+  ASSERT_TRUE(fs::exists(results_path_));
+
+  // Make sure the content is empty.
+  std::string content;
+  EXPECT_TRUE(readFile(results_path_, content));
+  EXPECT_EQ(content, "");
+}
+
+TEST_F(FilesystemLoggerTests, test_log_string) {
+  EXPECT_TRUE(logString("{\"json\": true}", "event"));
+
+  std::string content;
+  EXPECT_TRUE(readFile(results_path_, content));
+  EXPECT_EQ(content, "{\"json\": true}\n");
+}
+
+TEST_F(FilesystemLoggerTests, test_log_snapshot) {
+  QueryLogItem item;
+  item.name = "test";
+  item.identifier = "test";
+  item.time = 0;
+  item.calendar_time = "test";
+
+  EXPECT_TRUE(logSnapshotQuery(item));
+  auto snapshot_path = fs::path(FLAGS_logger_path) / "osqueryd.snapshots.log";
+  ASSERT_TRUE(fs::exists(snapshot_path));
+
+  // Write a second snapshot item, and make sure there is a newline between
+  // the two log lines.
+  EXPECT_TRUE(logSnapshotQuery(item));
+  std::string content;
+  EXPECT_TRUE(readFile(snapshot_path.string(), content));
+
+  std::string expected =
+      "{\"snapshot\":\"\",\"name\":\"test\",\"hostIdentifier\":\"test\","
+      "\"calendarTime\":\"test\",\"unixTime\":\"0\"}\n{\"snapshot\":\"\","
+      "\"name\":\"test\",\"hostIdentifier\":\"test\",\"calendarTime\":\"test\","
+      "\"unixTime\":\"0\"}\n";
+  EXPECT_EQ(content, expected);
+}
+}

osquery/logger/plugins/tls.h

@@ -63,8 +63,6 @@ class TLSLogForwarderRunner : public InternalRunnable {
 
 class TLSLoggerPlugin : public LoggerPlugin {
  public:
-  TLSLoggerPlugin() : log_index_(0) {}
-
   /**
    * @brief The osquery logger initialization method.
    *
@@ -93,7 +91,7 @@ class TLSLoggerPlugin : public LoggerPlugin {
    * second precision for indexing and ordering. log_index_ helps prevent
    * collisions by appending an auto-increment counter.
    */
-  size_t log_index_;
+  size_t log_index_{0};
 
  private:
   /// Allow the TLSLogForwardRunner thread to disable log buffering.

osquery/logger/tests/logger_tests.cpp

@@ -11,19 +11,18 @@
 #include <gtest/gtest.h>
 
 #include <osquery/core.h>
-#include <osquery/flags.h>
 #include <osquery/logger.h>
 
 namespace osquery {
 
-DECLARE_string(logger_plugin);
-
 class LoggerTests : public testing::Test {
  public:
   void SetUp() {
+    // Backup the logging status, then disable.
     logging_status_ = FLAGS_disable_logging;
     FLAGS_disable_logging = false;
 
+    // Setup / initialize static members.
     log_lines.clear();
     status_messages.clear();
     statuses_logged = 0;
@@ -49,7 +48,7 @@ class LoggerTests : public testing::Test {
 
  private:
   /// Save the status of logging before running tests, restore afterward.
-  bool logging_status_;
+  bool logging_status_{true};
 };
 
 std::vector<std::string> LoggerTests::log_lines;
@@ -62,8 +61,6 @@ int LoggerTests::health_status_rows = 0;
 
 class TestLoggerPlugin : public LoggerPlugin {
  public:
-  TestLoggerPlugin() {}
-
   Status logString(const std::string& s) {
     LoggerTests::log_lines.push_back(s);
     return Status(0, s);
@@ -100,8 +97,6 @@ class TestLoggerPlugin : public LoggerPlugin {
     LoggerTests::health_status_rows += 1;
     return Status(0, "OK");
   }
-
-  virtual ~TestLoggerPlugin() {}
 };
 
 TEST_F(LoggerTests, test_plugin) {
@@ -133,6 +128,23 @@ TEST_F(LoggerTests, test_logger_init) {
   EXPECT_EQ(LoggerTests::statuses_logged, 0);
 }
 
+TEST_F(LoggerTests, test_log_string) {
+  // So far, tests have only used the logger registry/plugin API.
+  EXPECT_TRUE(logString("{\"json\": true}", "event"));
+  ASSERT_EQ(LoggerTests::log_lines.size(), 1U);
+  EXPECT_EQ(LoggerTests::log_lines.back(), "{\"json\": true}");
+
+  // Expect the logString method to fail if we explicitly request a logger
+  // plugin that has not been added to the registry.
+  EXPECT_FALSE(logString("{\"json\": true}", "event", "does_not_exist"));
+
+  // Expect the plugin to receive logs if status logging is disabled.
+  FLAGS_disable_logging = true;
+  EXPECT_TRUE(logString("test", "event"));
+  EXPECT_EQ(LoggerTests::log_lines.size(), 2U);
+  FLAGS_disable_logging = false;
+}
+
 TEST_F(LoggerTests, test_logger_log_status) {
   // This will be printed to stdout.
   LOG(WARNING) << "Logger test is generating a warning status (2)";
@@ -175,15 +187,19 @@ TEST_F(LoggerTests, test_logger_snapshots) {
   EXPECT_EQ(LoggerTests::health_status_rows, 1);
 }
 
-class SecondTestLoggerPlugin : public TestLoggerPlugin {};
+class SecondTestLoggerPlugin : public LoggerPlugin {
+ public:
+  Status logString(const std::string& s) override { return Status(0); }
+};
 
 TEST_F(LoggerTests, test_multiple_loggers) {
   Registry::add<SecondTestLoggerPlugin>("logger", "second_test");
   EXPECT_TRUE(Registry::setActive("logger", "test,second_test").ok());
 
   // With two active loggers, the string should be added twice.
+  // But the 'test' logger is the only item incrementing the log_lines counter.
   logString("this is a test", "added");
-  EXPECT_EQ(LoggerTests::log_lines.size(), 2U);
+  EXPECT_EQ(LoggerTests::log_lines.size(), 1U);
 
   LOG(WARNING) << "Logger test is generating a warning status (4)";
   // Refer to the above notes about status logs not emitting until the logger
@@ -192,7 +208,7 @@ TEST_F(LoggerTests, test_multiple_loggers) {
   EXPECT_EQ(LoggerTests::statuses_logged, 0);
 
   // Now try to initialize multiple loggers (1) forwards, (2) does not.
-  Registry::setActive("logger", "test,filesystem");
+  Registry::setActive("logger", "test,second_test");
   initLogger("logger_test");
   LOG(WARNING) << "Logger test is generating a warning status (5)";
   // Now that the "test" logger is initialized, the status log will be
@@ -212,6 +228,13 @@ TEST_F(LoggerTests, test_logger_scheduled_query) {
 
   item.results.removed.push_back({{"test_column", "test_new_value\n"}});
   logQueryLogItem(item);
-  EXPECT_EQ(LoggerTests::log_lines.size(), 3U);
+  ASSERT_EQ(LoggerTests::log_lines.size(), 3U);
+
+  // Make sure the JSON output does not have a newline.
+  std::string expected =
+      "{\"name\":\"test_query\",\"hostIdentifier\":\"unknown_test_host\","
+      "\"calendarTime\":\"no_time\",\"unixTime\":\"0\",\"columns\":{\"test_"
+      "column\":\"test_new_value\\n\"},\"action\":\"removed\"}";
+  EXPECT_EQ(LoggerTests::log_lines.back(), expected);
 }
 }