Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 12 additions & 0 deletions toolbelt/BUILD.bazel
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,18 @@ cc_test(
],
)

cc_test(
name = "logging_test",
size = "small",
srcs = ["logging_test.cc"],
deps = [
":toolbelt",
"@com_google_absl//absl/status",
"@com_google_absl//absl/status:statusor",
"@com_google_googletest//:gtest_main",
],
)

cc_test(
name = "table_test",
size = "small",
Expand Down
80 changes: 80 additions & 0 deletions toolbelt/logging.h
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the idea of this. In fact, in my own company's logging library, we have similar perfect forwarding of the fmt+args down to the logging functions to present the user with a similarly convenient syntax.

One big design feature that I would very much recommend (and might be able to provide the code for), is to perfectly forward all the way down to the implementation of Log / VLog functions because that will allow for logging functions that do not require any dynamic memory allocation, which is very handy in real-time and signal handler contexts, and quite easy to do with the fmt library. I did this very easily, and I can remove malloc/free in some contexts and still log messages to stdout/stderr.

But, this will require rewriting Log/VLog completely. So, maybe something for @dallison to think about.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thats a good call. Will update. Thanks

Original file line number Diff line number Diff line change
Expand Up @@ -78,6 +78,86 @@ class Logger {
virtual void Log(LogLevel level, uint64_t timestamp,
const std::string &source, std::string text);

inline void VerboseDebug(const std::string& str) {
Log(LogLevel::kVERBOSE_DEBUG, str);
}
inline void Debug(const std::string& str) {
Log(LogLevel::kDBG, str);
}
inline void Info(const std::string& str) {
Log(LogLevel::kINFO, str);
}
inline void Warn(const std::string& str) {
Log(LogLevel::kWARNING, str);
}
inline void Error(const std::string& str) {
Log(LogLevel::kERROR, str);
}
inline void Fatal(const std::string& str) {
Log(LogLevel::kFATAL, str);
}
inline void VerboseDebug(std::string&& str) {
Log(LogLevel::kVERBOSE_DEBUG, std::move(str));
}
inline void Debug(std::string&& str) {
Log(LogLevel::kDBG, std::move(str));
}
inline void Info(std::string&& str) {
Log(LogLevel::kINFO, std::move(str));
}
inline void Warn(std::string&& str) {
Log(LogLevel::kWARNING, std::move(str));
}
inline void Error(std::string&& str) {
Log(LogLevel::kERROR, std::move(str));
}
inline void Fatal(std::string&& str) {
Log(LogLevel::kFATAL, std::move(str));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There isn't really a benefit to these rvalue overloads when the underlying function does not swallow up that object and thus can only really use it as a const-ref.

}

template<typename... Ts>
void VerboseDebug(const char* fmt, Ts&&... args) {
if (!_enabled || LogLevel::kVERBOSE_DEBUG < min_level_) {
return;
}
Log(LogLevel::kVERBOSE_DEBUG, fmt::format(fmt, std::forward<Ts>(args)...));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If this file is going to be using fmt, it needs to include the relevant headers and dependency in the bazel target.

}

template<typename... Ts>
void Debug(const char* fmt, Ts&&... args) {
if (!_enabled || LogLevel::kDBG < min_level_) {
return;
}
Log(LogLevel::DBG, fmt::format(fmt, std::forward<Ts>(args)...));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's a weird that when the user calls Log(lvl, str, a, b, c) (i.e., the vararg version) it gets formatted, under-the-hood, with the "printf" formatting, but then, if they call Info(str, a, b, c) it gets formatted with the python-style fmt specifications.

N.B.: I much prefer the fmt version, but I think it needs to be consistent.

}
template<typename... Ts>
void Info(const char* fmt, Ts&&... args) {
if (!_enabled || LogLevel::kINFO < min_level_) {
return;
}
Log(LogLevel::kINFO, fmt::format(fmt, std::forward<Ts>(args)...));
}
template<typename... Ts>
void Warn(const char* fmt, Ts&&... args) {
if (!_enabled || LogLevel::kWARNING < min_level_) {
return;
}
Log(LogLevel::kWARNING, fmt::format(fmt, std::forward<Ts>(args)...));
}
template<typename... Ts>
void Error(const char* fmt, Ts&&... args) {
if (!_enabled || LogLevel::kERROR < min_level_) {
return;
}
Log(LogLevel::kERROR, fmt::format(fmt, std::forward<Ts>(args)...));
}
template<typename... Ts>
void Fatal(const char* fmt, Ts&&... args) {
if (!_enabled || LogLevel::kFATAL < min_level_) {
return;
}
Log(LogLevel::kFATAL, fmt::format(fmt, std::forward<Ts>(args)...));
}
void SetTheme(LogTheme theme);

// All logged messages with a level below the min level will be
Expand Down
238 changes: 238 additions & 0 deletions toolbelt/logging_test.cc
Original file line number Diff line number Diff line change
@@ -0,0 +1,238 @@
#include "logging.h"
#include <gtest/gtest.h>

#include <unistd.h>

#include <cstdio>
#include <fstream>

TEST(LoggingTest, Disabled) {
toolbelt::Logger logger("foobar", false);
logger.log(toolbelt::LogLevel::kINFO, "this should not be logged");
}

TEST(LoggingTest, Levels) {
toolbelt::Logger logger;

struct Level {
std::string name;
toolbelt::LogLevel level;
} levels[] = {
{"verbose", toolbelt::LogLevel::kVERBOSE_DEBUG},
{"debug", toolbelt::LogLevel::kDBG},
{"info", toolbelt::LogLevel::kINFO},
{"warning", toolbelt::LogLevel::kWARNING},
{"error", toolbelt::LogLevel::kERROR},
{"fatal", toolbelt::LogLevel::FATAL},
};

for (auto& level : levels) {
logger.setLogLevel(level.name);
ASSERT_EQ(level.level, logger.getLogLevel());
}
logger.setLogLevel(toolbelt::LogLevel::kINFO);

logger.log(toolbelt::LogLevel::kVERBOSE_DEBUG, "verbose debug");
logger.log(toolbelt::LogLevel::kDBG, "debug");
logger.log(toolbelt::LogLevel::kINFO, "info");
logger.log(toolbelt::LogLevel::kWARNING, "warning");
logger.log(toolbelt::LogLevel::kERROR, "error");

EXPECT_DEATH(logger.log(toolbelt::LogLevel::FATAL, "fatal"), "fatal");
}

static void ReadAndCheck(FILE* fp, const char* s) {
char buf[256] = {};
fgets(buf, sizeof(buf), fp);
ASSERT_NE(nullptr, strstr(buf, s));
}

TEST(LoggingTest, Output) {
toolbelt::Logger logger;

int pipes[2];
(void)pipe(pipes);

FILE* logger_fp = fdopen(pipes[1], "w");
FILE* read_fp = fdopen(pipes[0], "r");
ASSERT_NE(nullptr, logger_fp);
ASSERT_NE(nullptr, read_fp);

logger.setOutputStream(logger_fp);

toolbelt::LogLevel levels[] = {
toolbelt::LogLevel::kVERBOSE_DEBUG,
toolbelt::LogLevel::kDBG,
toolbelt::LogLevel::kINFO,
toolbelt::LogLevel::kWARNING,
toolbelt::LogLevel::kERROR,
};

for (auto& min_level : levels) {
logger.setLogLevel(min_level);
for (auto& level : levels) {
logger.log(level, "foobar");
fflush(logger_fp);
if (level >= min_level) {
ReadAndCheck(read_fp, "foobar");
}
}
}

fclose(logger_fp);
fclose(read_fp);
}

TEST(LoggingTest, Plain) {
toolbelt::Logger defaultLogger("default", true, toolbelt::LogTheme::DEFAULT);
toolbelt::Logger lightLogger("light", true, toolbelt::LogTheme::LIGHT);
toolbelt::Logger darkLogger("dark", true, toolbelt::LogTheme::DARK);

defaultLogger.setDisplayMode(toolbelt::LogDisplayMode::PLAIN);
lightLogger.setDisplayMode(toolbelt::LogDisplayMode::PLAIN);
darkLogger.setDisplayMode(toolbelt::LogDisplayMode::PLAIN);

toolbelt::LogLevel levels[] = {
toolbelt::LogLevel::kVERBOSE_DEBUG,
toolbelt::LogLevel::kDBG,
toolbelt::LogLevel::kINFO,
toolbelt::LogLevel::kWARNING,
toolbelt::LogLevel::kERROR,
};

std::string message = "test ";
for (int i = 0; i < 100; i++) {
for (auto& level : levels) {
defaultLogger.setLogLevel(level);
lightLogger.setLogLevel(level);
darkLogger.setLogLevel(level);

defaultLogger.log(level, message);
lightLogger.log(level, message);
darkLogger.log(level, message);
}
message += "test ";
}
}

TEST(LoggingTest, Color) {
toolbelt::Logger defaultLogger("default", true, toolbelt::LogTheme::DEFAULT);
toolbelt::Logger lightLogger("light", true, toolbelt::LogTheme::LIGHT);
toolbelt::Logger darkLogger("dark", true, toolbelt::LogTheme::DARK);

defaultLogger.setDisplayMode(toolbelt::LogDisplayMode::COLOR);
lightLogger.setDisplayMode(toolbelt::LogDisplayMode::COLOR);
darkLogger.setDisplayMode(toolbelt::LogDisplayMode::COLOR);


toolbelt::LogLevel levels[] = {
toolbelt::LogLevel::kVERBOSE_DEBUG,
toolbelt::LogLevel::kDBG,
toolbelt::LogLevel::kINFO,
toolbelt::LogLevel::kWARNING,
toolbelt::LogLevel::kERROR,
};

std::string message = "test ";
for (int i = 0; i < 100; i++) {
for (auto& level : levels) {
defaultLogger.setLogLevel(level);
lightLogger.setLogLevel(level);
darkLogger.setLogLevel(level);

defaultLogger.log(level, message);
lightLogger.log(level, message);
darkLogger.log(level, message);
}
message += "test ";
}
}

TEST(LoggingTest, Columnar) {
toolbelt::Logger defaultLogger("default", true, toolbelt::LogTheme::DEFAULT);
toolbelt::Logger lightLogger("light", true, toolbelt::LogTheme::LIGHT);
toolbelt::Logger darkLogger("dark", true, toolbelt::LogTheme::DARK);

defaultLogger.setDisplayMode(toolbelt::LogDisplayMode::COLUMNAR, 120);
lightLogger.setDisplayMode(toolbelt::LogDisplayMode::COLUMNAR, 120);
darkLogger.setDisplayMode(toolbelt::LogDisplayMode::COLUMNAR, 120);

toolbelt::LogLevel levels[] = {
toolbelt::LogLevel::kVERBOSE_DEBUG,
toolbelt::LogLevel::kDBG,
toolbelt::LogLevel::kINFO,
toolbelt::LogLevel::kWARNING,
toolbelt::LogLevel::kERROR,
};

std::string message = "test ";
for (int i = 0; i < 100; i++) {
for (auto& level : levels) {
defaultLogger.setLogLevel(level);
lightLogger.setLogLevel(level);
darkLogger.setLogLevel(level);

defaultLogger.log(level, message);
lightLogger.log(level, message);
darkLogger.log(level, message);
}
message += "test ";
}
}

TEST(LoggingTest, ColumnarSplit) {
toolbelt::Logger defaultLogger("default", true, toolbelt::LogTheme::DEFAULT);
defaultLogger.setDisplayMode(toolbelt::LogDisplayMode::COLUMNAR, 60);
defaultLogger.log(
toolbelt::LogLevel::kINFO,
"now is the time for all good men to come to the aid of the party\n");
defaultLogger.log(
toolbelt::LogLevel::kINFO, "the quick brown fox\njumps over the\nlazy dog");
}


TEST(LoggingTest, ColumnarLongSubsystem) {
toolbelt::Logger longLogger(
"this_is_a_very_long_subsystem_name_just_to_get_coverage_of_a_line",
true,
toolbelt::LogTheme::DEFAULT);
longLogger.setDisplayMode(toolbelt::LogDisplayMode::COLUMNAR, 60);
longLogger.log(
toolbelt::LogLevel::kINFO,
"now is the time for all good men to come to the aid of the party\n");
longLogger.log(
toolbelt::LogLevel::kINFO, "the quick brown fox\njumps over the\nlazy dog");
}

TEST(LoggingTest, Tee) {
toolbelt::Logger logger("tee_test", true);
logger.setDisplayMode(toolbelt::LogDisplayMode::COLOR);

const std::string teeFile = "/tmp/foo/bar/tee_test.log";
auto status = logger.setTeeFile(teeFile);
ASSERT_TRUE(status.ok()) << status.toString();

logger.log(toolbelt::LogLevel::kINFO, "this is a test message");

std::ifstream teeStream(teeFile);
ASSERT_TRUE(teeStream.is_open());
std::string line;
std::getline(teeStream, line);
ASSERT_NE(line.find("this is a test message"), std::string::npos);
teeStream.close();

std::string tee2 = "/tmp/bar/foo/tee_test2.log";
// Use another tee file. This will close the previous one.
status = logger.setTeeFile(tee2);
ASSERT_TRUE(status.ok()) << status.toString();
logger.log(toolbelt::LogLevel::kINFO, "this is another test message");
std::ifstream teeStream2(tee2);
ASSERT_TRUE(teeStream2.is_open());
std::getline(teeStream2, line);
ASSERT_NE(line.find("this is another test message"), std::string::npos);
teeStream2.close();

// Clean up
remove(teeFile.c_str());
remove(tee2.c_str());
}