<commit_before>/**
 *  Copyright (c) 2014-present, Facebook, Inc.
 *  All rights reserved.
 *
 *  This source code is licensed in accordance with the terms specified in
 *  the LICENSE file found in the root directory of this source tree.
 */

#include <thread>

#include <gtest/gtest.h>

#include <osquery/data_logger.h>
#include <osquery/database.h>
#include <osquery/filesystem/filesystem.h>
#include <osquery/plugins/logger.h>
#include <osquery/registry_factory.h>
#include <osquery/system.h>
#include <osquery/utils/info/platform_type.h>
#include <osquery/utils/system/time.h>

namespace osquery {

DECLARE_bool(disable_database);
DECLARE_int32(logger_min_status);
DECLARE_int32(logger_min_stderr);
DECLARE_bool(logger_secondary_status_only);
DECLARE_bool(logger_status_sync);
DECLARE_bool(logger_event_type);
DECLARE_bool(logger_snapshot_event_type);
DECLARE_bool(disable_logging);
DECLARE_bool(logger_numerics);

class LoggerTests : public testing::Test {
 public:
  void SetUp() override {
    Initializer::platformSetup();
    registryAndPluginInit();
    FLAGS_disable_database = true;
    DatabasePlugin::setAllowOpen(true);
    DatabasePlugin::initPlugin();

    // Backup the logging status, then disable.
    FLAGS_disable_logging = false;
    FLAGS_logger_status_sync = true;

    // Setup / initialize static members.
    log_lines.clear();
    status_messages.clear();
    statuses_logged = 0;
    last_status = {O_INFO, "", 10, "", "cal_time", 0, "host"};
  }

  void TearDown() override {}

  // Track lines emitted to logString
  static std::vector<std::string> log_lines;

  // Track the results of init
  static StatusLogLine last_status;
  static std::vector<std::string> status_messages;

  // Count calls to logStatus
  static size_t statuses_logged;
  static size_t events_logged;
  // Count added and removed snapshot rows
  static size_t snapshot_rows_added;
  static size_t snapshot_rows_removed;
};

std::vector<std::string> LoggerTests::log_lines;
StatusLogLine LoggerTests::last_status;
std::vector<std::string> LoggerTests::status_messages;
size_t LoggerTests::statuses_logged = 0;
size_t LoggerTests::events_logged = 0;
size_t LoggerTests::snapshot_rows_added = 0;
size_t LoggerTests::snapshot_rows_removed = 0;

inline void placeStatuses(const std::vector<StatusLogLine>& log) {
  for (const auto& status : log) {
    LoggerTests::status_messages.push_back(status.message);
  }

  LoggerTests::statuses_logged += log.size();
  if (log.size() > 0) {
    LoggerTests::last_status = log.back();
  }
}

class TestLoggerPlugin : public LoggerPlugin {
 protected:
  bool usesLogStatus() override {
    return shouldLogStatus;
  }

  bool usesLogEvent() override {
    return shouldLogEvent;
  }

  Status logEvent(const std::string& e) override {
    LoggerTests::events_logged++;
    return Status::success();
  }

  Status logString(const std::string& s) override {
    LoggerTests::log_lines.push_back(s);
    return Status(0, s);
  }

  void init(const std::string& name,
            const std::vector<StatusLogLine>& log) override {
    placeStatuses(log);
  }

  Status logStatus(const std::vector<StatusLogLine>& log) override {
    placeStatuses(log);
    return Status::success();
  }

  Status logSnapshot(const std::string& s) override {
    LoggerTests::snapshot_rows_added += 1;
    LoggerTests::snapshot_rows_removed += 0;
    return Status::success();
  }

 public:
  /// Allow test methods to change status logging state.
  bool shouldLogStatus{true};

  /// Allow test methods to change event logging state.
  bool shouldLogEvent{true};
};

TEST_F(LoggerTests, test_plugin) {
  auto& rf = RegistryFactory::get();
  rf.registry("logger")->add("test", std::make_shared<TestLoggerPlugin>());
  rf.setUp();

  auto s = Registry::call("logger", "test", {{"string", "foobar"}});
  EXPECT_TRUE(s.ok());
  EXPECT_EQ("foobar", LoggerTests::log_lines.back());
}

TEST_F(LoggerTests, test_logger_init) {
  auto& rf = RegistryFactory::get();
  // Expect the logger to have been registered from the first test.
  EXPECT_TRUE(rf.exists("logger", "test"));
  EXPECT_TRUE(rf.setActive("logger", "test").ok());

  initStatusLogger("logger_test");
  // This will be printed to stdout.
  LOG(WARNING) << "Logger test is generating a warning status (1)";
  initLogger("logger_test");

  // The warning message will have been buffered and sent to the active logger
  // which is test.
  EXPECT_EQ(1U, LoggerTests::status_messages.size());
  EXPECT_EQ(1U, LoggerTests::statuses_logged);
}

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(1U, LoggerTests::log_lines.size());
  EXPECT_EQ("{\"json\": true}", LoggerTests::log_lines.back());

  // 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 not to receive logs if status logging is disabled.
  FLAGS_disable_logging = true;
  EXPECT_TRUE(logString("test", "event"));
  EXPECT_EQ(1U, LoggerTests::log_lines.size());
  FLAGS_disable_logging = false;

  // If logging is re-enabled, logs should send as usual.
  EXPECT_TRUE(logString("test", "event"));
  EXPECT_EQ(2U, LoggerTests::log_lines.size());
}

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) << 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) {
  const auto logger_min_status = FLAGS_logger_min_status;
  FLAGS_logger_min_status = 0;
  // This will be printed to stdout.
  LOG(INFO) << "Logger test is generating an info status";
  EXPECT_EQ(1U, LoggerTests::statuses_logged);

  FLAGS_logger_min_status = 1;
  setVerboseLevel();

  LOG(INFO) << "Logger test is generating an info status";<commit_msg>Fix flaky LoggerTests.test_logger_log_status (#6171)<commit_after>/**
 *  Copyright (c) 2014-present, Facebook, Inc.
 *  All rights reserved.
 *
 *  This source code is licensed in accordance with the terms specified in
 *  the LICENSE file found in the root directory of this source tree.
 */

#include <thread>

#include <gtest/gtest.h>

#include <osquery/data_logger.h>
#include <osquery/database.h>
#include <osquery/filesystem/filesystem.h>
#include <osquery/plugins/logger.h>
#include <osquery/registry_factory.h>
#include <osquery/system.h>
#include <osquery/utils/info/platform_type.h>
#include <osquery/utils/system/time.h>

namespace osquery {

DECLARE_bool(disable_database);
DECLARE_int32(logger_min_status);
DECLARE_int32(logger_min_stderr);
DECLARE_bool(logger_secondary_status_only);
DECLARE_bool(logger_status_sync);
DECLARE_bool(logger_event_type);
DECLARE_bool(logger_snapshot_event_type);
DECLARE_bool(disable_logging);
DECLARE_bool(logger_numerics);

class LoggerTests : public testing::Test {
 public:
  void SetUp() override {
    Initializer::platformSetup();
    registryAndPluginInit();
    FLAGS_disable_database = true;
    DatabasePlugin::setAllowOpen(true);
    DatabasePlugin::initPlugin();

    // Backup the logging status, then disable.
    FLAGS_disable_logging = false;
    FLAGS_logger_status_sync = true;

    // Setup / initialize static members.
    log_lines.clear();
    status_messages.clear();
    statuses_logged = 0;
    last_status = {O_INFO, "", 10, "", "cal_time", 0, "host"};
  }

  void TearDown() override {}

  // Track lines emitted to logString
  static std::vector<std::string> log_lines;

  // Track the results of init
  static StatusLogLine last_status;
  static std::vector<std::string> status_messages;

  // Count calls to logStatus
  static size_t statuses_logged;
  static size_t events_logged;
  // Count added and removed snapshot rows
  static size_t snapshot_rows_added;
  static size_t snapshot_rows_removed;
};

std::vector<std::string> LoggerTests::log_lines;
StatusLogLine LoggerTests::last_status;
std::vector<std::string> LoggerTests::status_messages;
size_t LoggerTests::statuses_logged = 0;
size_t LoggerTests::events_logged = 0;
size_t LoggerTests::snapshot_rows_added = 0;
size_t LoggerTests::snapshot_rows_removed = 0;

inline void placeStatuses(const std::vector<StatusLogLine>& log) {
  for (const auto& status : log) {
    LoggerTests::status_messages.push_back(status.message);
  }

  LoggerTests::statuses_logged += log.size();
  if (log.size() > 0) {
    LoggerTests::last_status = log.back();
  }
}

class TestLoggerPlugin : public LoggerPlugin {
 protected:
  bool usesLogStatus() override {
    return shouldLogStatus;
  }

  bool usesLogEvent() override {
    return shouldLogEvent;
  }

  Status logEvent(const std::string& e) override {
    LoggerTests::events_logged++;
    return Status::success();
  }

  Status logString(const std::string& s) override {
    LoggerTests::log_lines.push_back(s);
    return Status(0, s);
  }

  void init(const std::string& name,
            const std::vector<StatusLogLine>& log) override {
    placeStatuses(log);
  }

  Status logStatus(const std::vector<StatusLogLine>& log) override {
    placeStatuses(log);
    return Status::success();
  }

  Status logSnapshot(const std::string& s) override {
    LoggerTests::snapshot_rows_added += 1;
    LoggerTests::snapshot_rows_removed += 0;
    return Status::success();
  }

 public:
  /// Allow test methods to change status logging state.
  bool shouldLogStatus{true};

  /// Allow test methods to change event logging state.
  bool shouldLogEvent{true};
};

TEST_F(LoggerTests, test_plugin) {
  auto& rf = RegistryFactory::get();
  rf.registry("logger")->add("test", std::make_shared<TestLoggerPlugin>());
  rf.setUp();

  auto s = Registry::call("logger", "test", {{"string", "foobar"}});
  EXPECT_TRUE(s.ok());
  EXPECT_EQ("foobar", LoggerTests::log_lines.back());
}

TEST_F(LoggerTests, test_logger_init) {
  auto& rf = RegistryFactory::get();
  // Expect the logger to have been registered from the first test.
  EXPECT_TRUE(rf.exists("logger", "test"));
  EXPECT_TRUE(rf.setActive("logger", "test").ok());

  initStatusLogger("logger_test");
  // This will be printed to stdout.
  LOG(WARNING) << "Logger test is generating a warning status (1)";
  initLogger("logger_test");

  // The warning message will have been buffered and sent to the active logger
  // which is test.
  EXPECT_EQ(1U, LoggerTests::status_messages.size());
  EXPECT_EQ(1U, LoggerTests::statuses_logged);
}

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(1U, LoggerTests::log_lines.size());
  EXPECT_EQ("{\"json\": true}", LoggerTests::log_lines.back());

  // 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 not to receive logs if status logging is disabled.
  FLAGS_disable_logging = true;
  EXPECT_TRUE(logString("test", "event"));
  EXPECT_EQ(1U, LoggerTests::log_lines.size());
  FLAGS_disable_logging = false;

  // If logging is re-enabled, logs should send as usual.
  EXPECT_TRUE(logString("test", "event"));
  EXPECT_EQ(2U, LoggerTests::log_lines.size());
}

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) << 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(LoggerTests::last_status.time, now);
  EXPECT_EQ(getHostIdentifier(), LoggerTests::last_status.identifier);
}

TEST_F(LoggerTests, test_logger_status_level) {
  const auto logger_min_status = FLAGS_logger_min_status;
  FLAGS_logger_min_status = 0;
  // This will be printed to stdout.
  LOG(INFO) << "Logger test is generating an info status";
  EXPECT_EQ(1U, LoggerTests::statuses_logged);

  FLAGS_logger_min_status = 1;
  setVerboseLevel();

  LOG(INFO) << "Logger test is generating an info status";
{'fraction_non_alphanumeric': 0.12465870972774787, 'fraction_numerical': 0.005304625945861612, 'mean_word_length': 5.015954950727358, 'pattern_counts': {'":': 6, '<': 55, '<?xml version=': 0, '>': 43, 'https://': 0, 'lorem ipsum': 0, 'www.': 0, 'xml': 0}, 'pii_count': 0, 'substrings_counts': 0, 'word_list_counts': {'cursed_substrings.json': 2, 'profanity_word_list.json': 0, 'sexual_word_list.json': 0, 'zh_pornsignals.json': 0}}
{'dir': 'git-commits-cleaned', 'id': '6178138', 'n_tokens_mistral': 4142, 'n_tokens_neox': 4033, 'n_words': 994}