query/test/core/logger/LoggerTest.cpp

#include <catch2/catch_test_macros.hpp>

#include "matador/logger/log_manager.hpp"

#include "matador/utils/os.hpp"

#ifdef _MSC_VER
#include <io.h>
#else
#include <unistd.h>
#endif

#include <fstream>
#include <regex>
#include <sstream>

using namespace matador::logger;

namespace filehelper {

class std_stream_switcher
{
public:
    explicit std_stream_switcher(FILE *str, const char* redirect)
    : stream(str) {
        fflush(stream);
        fgetpos(stream, &pos);
        fd = matador::os::dup(stream);
        matador::os::freopen(redirect, "w+", stream);
    }
    ~std_stream_switcher() {
        fflush(stream);
#ifdef _MSC_VER
        _dup2(fd, _fileno(stream));
        _close(fd);
#else
        dup2(fd, fileno(stream));
        close(fd);
#endif
        clearerr(stream);
        fsetpos(stream, &pos);
    }

private:
    FILE *stream = nullptr;
    int fd = 0;
    fpos_t pos = {};
};

}

void validate_log_file_line(const std::string &filename, int line_index, const std::string &level, const std::string &src, const std::string &msg);

TEST_CASE("Test log file sink", "[logger][log][file_sink]") {
    file_sink test("test.txt");

    REQUIRE(matador::os::exists("test.txt"));

    //  UNIT_ASSERT_EQUAL("test.txt", test.path());

    test.close();

    if (::remove("test.txt") == -1) {
#ifdef _MSC_VER
        char buf[1024];
        strerror_s(buf, 1024, errno);
        FAIL(buf);
#else
        UNIT_FAIL(strerror(errno));
#endif
    }

    REQUIRE(!matador::os::exists("test.txt"));

    {
        auto path = matador::os::build_path("mylog", "test.txt");
        file_sink test2(path);

        REQUIRE("mylog" == test2.path());

        matador::os::chdir("mylog");

        REQUIRE(matador::os::exists("test.txt"));

    }
    if (::remove("test.txt") == -1) {
#ifdef _MSC_VER
        char buf[1024];
        strerror_s(buf, 1024, errno);
        FAIL(buf);
#else
        UNIT_FAIL(strerror(errno));
#endif
    }

    REQUIRE(!matador::os::exists("test.txt"));

    matador::os::chdir("..");

    matador::os::rmdir("mylog");
}

TEST_CASE("Test log rotating file sink", "[logger][log][rotate_file_sink]") {
    const auto dir = matador::os::build_path("my", "log");
    const auto path = matador::os::build_path(dir, "log.txt");

    const auto logsink = create_rotating_file_sink(path, 30, 3);

    matador::os::chdir(dir);

    REQUIRE(matador::os::is_readable("log.txt"));
    REQUIRE(matador::os::is_writable("log.txt"));

    std::string line = "hello world and first line\n";

    logsink->write(line.c_str(), line.size());

    matador::os::chdir("my");
    matador::os::chdir("log");

    REQUIRE(!matador::os::exists("log.1.txt"));

    logsink->write(line.c_str(), line.size());

    REQUIRE(matador::os::exists("log.1.txt"));

    logsink->close();

    matador::os::remove("log.txt");
    matador::os::remove("log.1.txt");

    matador::os::chdir("..");
    matador::os::chdir("..");

    matador::os::rmpath(matador::os::build_path("my", "log"));
}

TEST_CASE("Test log level range", "[logger][level][range]") {
    REQUIRE(log_level::LVL_INFO == log_manager::min_default_log_level());
    REQUIRE(log_level::LVL_FATAL == log_manager::max_default_log_level());

    default_min_log_level(log_level::LVL_DEBUG);
    default_max_log_level(log_level::LVL_ERROR);

    REQUIRE(log_level::LVL_DEBUG == log_manager::min_default_log_level());
    REQUIRE(log_level::LVL_ERROR == log_manager::max_default_log_level());

    log_level_range llr;
    llr.min_level = log_level::LVL_DEBUG;
    llr.max_level = log_level::LVL_TRACE;
    log_domain ld("test", llr);

    REQUIRE(log_level::LVL_DEBUG == ld.min_log_level());
    REQUIRE(log_level::LVL_TRACE == ld.max_log_level());

    ld.min_log_level(log_level::LVL_INFO);
    ld.max_log_level(log_level::LVL_ERROR);

    REQUIRE(log_level::LVL_INFO == ld.min_log_level());
    REQUIRE(log_level::LVL_ERROR == ld.max_log_level());
}

TEST_CASE("Test basic logger functions", "[logger][basic]") {
    auto logger = create_logger("test");

    REQUIRE("test" == logger.source());
    REQUIRE("default" == logger.domain());

    auto logsink = create_file_sink("log.txt");

    REQUIRE(matador::os::is_readable("log.txt"));
    REQUIRE(matador::os::is_writable("log.txt"));

    logsink->close();

    if (::remove("log.txt") == -1) {
#ifdef _MSC_VER
        char buf[1024];
        strerror_s(buf, 1024, errno);
        FAIL(buf);
#else
        FAIL(strerror(errno));
#endif
    }

    REQUIRE(!matador::os::exists("log.txt"));

    logger = create_logger("net", "system");

    REQUIRE("net" == logger.source());
    REQUIRE("system" == logger.domain());

    logsink = create_file_sink("net.txt");

    REQUIRE(matador::os::is_readable("net.txt"));
    REQUIRE(matador::os::is_writable("net.txt"));

    logsink->close();

    matador::os::remove("net.txt");

    REQUIRE(!matador::os::exists("net.txt"));

    log_manager::instance().clear();
}

TEST_CASE("Test logging", "[logger][logging]") {
  domain_min_log_level("default", log_level::LVL_FATAL);
  domain_max_log_level("default", log_level::LVL_TRACE);

  auto logger = create_logger("test");

  REQUIRE("test" == logger.source());
  REQUIRE("default" == logger.domain());

  auto logsink = create_file_sink("log.txt");

  REQUIRE(matador::os::is_readable("log.txt"));
  REQUIRE(matador::os::is_writable("log.txt"));

  add_log_sink(logsink);

  logger.info("information");
  logger.info("information %s", "important");
  logger.warn("warning");
  logger.warn("warning %s", "important");
  logger.debug("debugging");
  logger.debug("debugging %s", "important");
  logger.trace("tracing something");
  logger.trace("tracing something %s", "important");
  logger.error("big error");
  logger.error("big error %s", "important");
  log(log_level::LVL_ERROR, "test", "global log test %d", 4711);

  logsink->close();

  validate_log_file_line("log.txt", 0, "INFO", "test", "information");
  validate_log_file_line("log.txt", 1, "INFO", "test", "information important");
  validate_log_file_line("log.txt", 2, "WARN", "test", "warning");
  validate_log_file_line("log.txt", 3, "WARN", "test", "warning important");
  validate_log_file_line("log.txt", 4, "DEBUG", "test", "debugging");
  validate_log_file_line("log.txt", 5, "DEBUG", "test", "debugging important");
  validate_log_file_line("log.txt", 6, "TRACE", "test", "tracing something");
  validate_log_file_line("log.txt", 7, "TRACE", "test", "tracing something important");
  validate_log_file_line("log.txt", 8, "ERROR", "test", "big error");
  validate_log_file_line("log.txt", 9, "ERROR", "test", "big error important");
  validate_log_file_line("log.txt", 10, "ERROR", "test", "global log test 4711");

  matador::os::remove("log.txt");

  REQUIRE(!matador::os::exists("log.txt"));

  log_manager::instance().clear();
}

TEST_CASE("Test log stdout", "[logger][logging][stdout]") {
  auto logger = create_logger("test");

  REQUIRE("test" == logger.source());
  REQUIRE("default" == logger.domain());

  auto logsink = create_stdout_sink();

  // Redirect stdout
  {
    filehelper::std_stream_switcher stdout_switcher(stdout, "stdout.txt");
    add_log_sink(logsink);
    logger.info("information");
  }

  logsink->close();

  validate_log_file_line("stdout.txt", 0, "INFO", "test", "information");

  matador::os::remove("stdout.txt");

  REQUIRE(!matador::os::exists("stdout.txt"));

  log_manager::instance().clear();
}

TEST_CASE("Test log stderr", "[logger][logging][stderr]") {
    auto logger = create_logger("test");

    REQUIRE("test" == logger.source());
    REQUIRE("default" == logger.domain());

    auto logsink = create_stderr_sink();

    // Redirect stdout
    {
        filehelper::std_stream_switcher stdout_switcher(stderr, "stderr.txt");
        add_log_sink(logsink);
        logger.info("information");
    }

    logsink->close();

    validate_log_file_line("stderr.txt", 0, "INFO", "test", "information");

    matador::os::remove("stderr.txt");

    REQUIRE(!matador::os::exists("stderr.txt"));

    log_manager::instance().clear();
}

TEST_CASE("Test log levels", "[logger][levels]") {
    std::stringstream out;

    out << log_level::LVL_ERROR;

    REQUIRE("ERROR" == out.str());

    out.str("");
    out.clear();
    out << log_level::LVL_DEBUG;

    REQUIRE("DEBUG" == out.str());

    out.str("");
    out.clear();
    out << log_level::LVL_INFO;

    REQUIRE("INFO" == out.str());

    out.str("");
    out.clear();
    out << log_level::LVL_FATAL;

    REQUIRE("FATAL" == out.str());

    out.str("");
    out.clear();
    out << log_level::LVL_TRACE;

    REQUIRE("TRACE" == out.str());

    out.str("");
    out.clear();
    out << log_level::LVL_WARN;

    REQUIRE("WARN" == out.str());

    out.str("");
    out.clear();
    out << log_level::LVL_ALL;

    REQUIRE("ALL" == out.str());
}

void validate_log_file_line(const std::string &filename, int line_index, const std::string &level, const std::string &src, const std::string &msg) {
    std::ifstream logfile(filename);

    REQUIRE(logfile.good());

    std::string line;
    int line_count = 0;
    do {
        if (!std::getline(logfile, line).good()) {
            FAIL("couldn't find line");
        }
    } while (line_count++ < line_index);

    const std::regex logline_regex(R"(^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d{3}.*\[([A-Z]+)\s*\] \[(.*)\]: (.*)$)");
    std::smatch match;

    REQUIRE(std::regex_match(line, match, logline_regex));
    REQUIRE(4 == match.size());

    REQUIRE(level == match[1].str());
    REQUIRE(src ==match[2].str());
    REQUIRE(msg == match[3].str());
}