4
\$\begingroup\$

Source Code

I've attempted to create a simple logging library in cpp. My goal was to make it lightweight to incorporate and easy to add to the codebase.

/**
 * @file herrlog.hh
 * @author Saphereye
 * @brief Header file only logging library
 * @version 0.5
 * @date 2023-12-30
 *
 * @copyright Copyright (c) 2023
 */

#pragma once

#include <chrono>
#include <fstream>
#include <iostream>
#include <ostream>
#include <mutex>

/**
 * @brief Set of ANSI colors, more can be found here:
 * https://gist.github.com/JBlond/2fea43a3049b38287e5e9cefc87b2124
 *
 */
#define RESET_COLOR "\033[0m"
#define BOLD_RED_COLOR "\033[1;31m"
#define BOLD_GREEN_COLOR "\033[1;32m"
#define BOLD_YELLOW_COLOR "\033[1;33m"
#define BOLD_BLUE_COLOR "\033[1;34m"
#define BACKGROUND_RED_COLOR "\033[41m"
#define BOLD_WHITE_COLOR "\033[1;37m"

/**
 * @brief Enum defining different log types as bit flags.
 *
 */
enum class LogType : std::uint8_t {
    Trace = 0b000001,  // For specific details
    Debug = 0b000010,  // Temporary debug printing
    Info = 0b000100,   // General purpose details, e.g. "Program has started"
    Error = 0b001000,  // For errors, exits the program
    Warn = 0b010000,   // For reporting warning, the program keeps working
    Fatal = 0b100000,  // Program exits and produces core dump

    All = 0b111111,
    None = 0b000000,
};

/**
 * @brief Overloading the `|` operator for combining log types.
 *
 * @param a
 * @param b
 * @return LogType
 */
LogType operator|(LogType a, LogType b) {
    return static_cast<LogType>(static_cast<uint8_t>(a) |
                                static_cast<uint8_t>(b));
}

/**
 * @brief Overloading the `&` operator for checking if a log type is set.
 *
 * @param a
 * @param b
 * @return true
 * @return false
 */
bool operator&(LogType a, LogType b) {
    return static_cast<bool>(static_cast<uint8_t>(a) & static_cast<uint8_t>(b));
}

/**
 * @brief Logger implementation providing flexible logging capabilities.
 *
 */
class Logger {
   private:
    static LogType log_type;
    static std::string output_file_name;
    static std::ofstream output_file;
    static bool is_output_to_console;
    static const char* datetime_format;
    static std::mutex log_mutex;

    /**
     * @brief A recursive function to print the templated arguments passed
     *
     * @tparam T
     * @tparam Rest
     * @param stream
     * @param format
     * @param arg
     * @param rest
     */
    template <typename T, typename... Rest>
    static void print_to_stream(std::ostream& stream, const char* format, T arg,
                                Rest... rest) {
        for (size_t index = 0; format[index] != '\0'; index++) {
            if (format[index] == '{' && format[index + 1] == '}') {
                stream << arg;
                return print_to_stream(stream, format + index + 2, rest...);
            }
            stream << format[index];
        }
    }

    /**
     * @brief Base case for the recursive function
     *
     * @param stream
     * @param format
     */
    static void print_to_stream(std::ostream& stream, const char* format) {
        for (size_t index = 0; format[index] != '\0'; index++) {
            stream << format[index];
        }
    }

    /**
     * @brief Logs a message with specified details to the console or a file.
     *
     * @tparam Args
     * @param name
     * @param color
     * @param format
     * @param args
     */
    template <typename... Args>
    static void log(const char* name, const char* color, const char* format,
                    Args... args) {
        auto current_time_point = std::chrono::system_clock::now();
        std::time_t current_time =
            std::chrono::system_clock::to_time_t(current_time_point);
        char time_string[100];
        std::strftime(time_string, sizeof(time_string), datetime_format,
                      std::localtime(&current_time));

        std::lock_guard<std::mutex> lock(Logger::log_mutex);
        if (is_output_to_console) {
            std::cout << color << "[" << name << " " << time_string << "]"
                      << RESET_COLOR << " ";
            print_to_stream(std::cout, format, args...);
            std::cout << std::endl;
        } else {
            output_file << "[" << name << " " << time_string << "] ";
            print_to_stream(output_file, format, args...);
            output_file << "\n";
        }
    }

    /**
     * @brief Preventing construction of a new logger object.
     *
     */
    Logger() = delete;

   public:
    /**
     * @brief Sets the log type, default is LogType::All.
     *
     * @param log_type
     */
    static void set_type(LogType log_type) { Logger::log_type = log_type; }

    /**
     * @brief Set the output file name object
     *
     * @param output_file_name
     */
    static void set_output_file_name(std::string output_file_name) {
        Logger::output_file_name = output_file_name;
        is_output_to_console = false;
        Logger::output_file = std::ofstream(Logger::output_file_name);
        if (Logger::output_file.is_open()) {
            Logger::output_file.close();
        }
        Logger::output_file.open(Logger::output_file_name);
    }

    /**
     * @brief Set the datetime format object, default is "%Y-%m-%d %H:%M:%S"
     *
     * @param datetime_format
     */
    static void set_datetime_format(const char* datetime_format) {
        Logger::datetime_format = datetime_format;
    }

    /**
     * @brief Logs messages of type trace.
     *
     * @tparam Args
     * @param name
     * @param color
     * @param format
     * @param args
     */
    template <typename... Args>
    static void trace(const char* format, Args... args) {
        if (log_type & LogType::Trace) {
            log("TRACE", BOLD_WHITE_COLOR, format, args...);
        }
    }

    /**
     * @brief Logs messages of type debug
     *
     * @tparam Args
     * @param name
     * @param color
     * @param format
     * @param args
     */
    template <typename... Args>
    static void debug(const char* format, Args... args) {
        if (log_type & LogType::Debug) {
            log("DEBUG", BOLD_BLUE_COLOR, format, args...);
        }
    }

    /**
     * @brief Logs messages of type info
     *
     * @tparam Args
     * @param name
     * @param color
     * @param format
     * @param args
     */
    template <typename... Args>
    static void info(const char* format, Args... args) {
        if (log_type & LogType::Info) {
            log(" INFO", BOLD_GREEN_COLOR, format, args...);
        }
    }

    /**
     * @brief Logs messages of type error. Furthermore closes the output file
     * and exits the program.
     *
     * @tparam Args
     * @param name
     * @param color
     * @param format
     * @param args
     */
    template <typename... Args>
    static void error(const char* format, Args... args) {
        if (log_type & LogType::Error) {
            log("ERROR", BOLD_RED_COLOR, format, args...);
            if (!is_output_to_console) {
                output_file.close();
            }
            exit(EXIT_FAILURE);
        }
    }

    /**
     * @brief Logs messages of type warning. Doesn't exit the program, just
     * notifies the issue.
     *
     * @tparam Args
     * @param format
     * @param args
     */
    template <typename... Args>
    static void warn(const char* format, Args... args) {
        if (log_type & LogType::Warn) {
            log(" WARN", BOLD_YELLOW_COLOR, format, args...);
        }
    }

    /**
     * @brief Logs messages of type fatal. Exits the program and creates a core
     * dump.
     *
     * @tparam Args
     * @param format
     * @param args
     */
    template <typename... Args>
    static void fatal(const char* format, Args... args) {
        if (log_type & LogType::Fatal) {
            log("FATAL", BACKGROUND_RED_COLOR, format, args...);
            if (!is_output_to_console) {
                output_file.close();
            }
            abort();
        }
    }
};

LogType Logger::log_type = LogType::All;
std::string Logger::output_file_name = std::string();
std::ofstream Logger::output_file;
bool Logger::is_output_to_console = true;
const char* Logger::datetime_format = "%Y-%m-%d %H:%M:%S";
std::mutex Logger::log_mutex;

Example Usage

#include "herrlog.hh"

int main() {
    Logger::set_output_file_name("test.log"); // The output will be redirected to "test.log"
    Logger::trace("This is trace message number 1");
}

Which will write [TRACE 2023-12-31 12:41:09] This is trace message number 1 to the file test.log

Issue/Grievances

  • If the file option is chosen, the script writes to the file every time a logging function is called. My logic was that if it writes all the logs to a temporary buffer and then proceeds to write it to a file at the end of execution, all the logs will be lost in case of premature termination.
  • Currently, I am using helper methods such as set_output_file_name, set_type and set_datetime_format to set my respective variables. Initially, I had planned to use an init function, which takes all the parameters. But it doesn't cover all cases in which the user wants to give input. I tried the following.
    • Create all permutations of the function and put default values for each variable. This was a quick and dirty solution, but if I plan to increase variables, this will increase dramatically (O(n!))
    • I planned on using the boost library's name parameters. However, as I plan to create a single header library, I am unsure how to add that.

Final comments

I would really appreciate your input and suggestions on this and thank you for your time.

\$\endgroup\$
3
  • \$\begingroup\$ Just a note about writing in each call: You could push the entry into a queue, which is then served by a separate thread. \$\endgroup\$
    – uli
    Jan 3 at 11:53
  • \$\begingroup\$ What I don't like is that trace(" STufff", val1(), val2(), val3()); Is forced to call val1() and val2() and val3() even if no logging is going to happen. In production code when I know my service is stable I would want to disable all but the most serious logging information to get the top throughput. Most logging libraries use some macros to prevent extra code being called when logging is not going to happen. \$\endgroup\$ Jan 8 at 22:58
  • \$\begingroup\$ Why can't I send information to the syslog? \$\endgroup\$ Jan 8 at 23:01

2 Answers 2

3
\$\begingroup\$

Here are some things that may help you improve your program.

Don't hold a lock that might call external code

Consider this admittedly perverse little program:

#include "herrlog.h"
#include <thread>

using namespace std::chrono_literals;
struct Roadblock {
    std::chrono::duration<long> delay = 10s;
};

std::ostream& operator<<(std::ostream& out, const Roadblock& rb) {
    std::this_thread::sleep_for(rb.delay);
    return out << "What a refreshing sleep!";
}

void countdown(int initial, int identity) {
    Roadblock block{1s};
    for (int i = initial; i; --i) {
        Logger::warn("{}: count = {}, {}", identity, i, block);
    }
}
 
int main() {
    Roadblock roadblock{};
    Logger::trace("This is trace message number 1");
    std::jthread t1(countdown, 10, 1);
    std::jthread t2(countdown, 10, 2);
    Logger::info("roadblock says \"{}\"", roadblock);
    Logger::trace("This is trace message number 2");
}

The code right now grabs the mutex and then invokes the inserter for that object. It should be the other way around to minimize the time that the lock is held. Here's a trace of that program with the mutex as is:

[TRACE 2024-01-01 09:37:00] This is trace message number 1
[ WARN 2024-01-01 09:37:00] 1: count = 10, What a refreshing sleep!
[ WARN 2024-01-01 09:37:01] 1: count = 9, What a refreshing sleep!
[ WARN 2024-01-01 09:37:02] 1: count = 8, What a refreshing sleep!
[ WARN 2024-01-01 09:37:03] 1: count = 7, What a refreshing sleep!
[ WARN 2024-01-01 09:37:04] 1: count = 6, What a refreshing sleep!
[ INFO 2024-01-01 09:37:00] roadblock says "What a refreshing sleep!"
[TRACE 2024-01-01 09:37:15] This is trace message number 2
[ WARN 2024-01-01 09:37:00] 2: count = 10, What a refreshing sleep!
[ WARN 2024-01-01 09:37:16] 2: count = 9, What a refreshing sleep!
[ WARN 2024-01-01 09:37:17] 2: count = 8, What a refreshing sleep!
[ WARN 2024-01-01 09:37:18] 2: count = 7, What a refreshing sleep!
[ WARN 2024-01-01 09:37:19] 2: count = 6, What a refreshing sleep!
[ WARN 2024-01-01 09:37:20] 2: count = 5, What a refreshing sleep!
[ WARN 2024-01-01 09:37:21] 2: count = 4, What a refreshing sleep!
[ WARN 2024-01-01 09:37:22] 2: count = 3, What a refreshing sleep!
[ WARN 2024-01-01 09:37:23] 2: count = 2, What a refreshing sleep!
[ WARN 2024-01-01 09:37:24] 2: count = 1, What a refreshing sleep!
[ WARN 2024-01-01 09:37:05] 1: count = 5, What a refreshing sleep!
[ WARN 2024-01-01 09:37:26] 1: count = 4, What a refreshing sleep!
[ WARN 2024-01-01 09:37:27] 1: count = 3, What a refreshing sleep!
[ WARN 2024-01-01 09:37:28] 1: count = 2, What a refreshing sleep!
[ WARN 2024-01-01 09:37:29] 1: count = 1, What a refreshing sleep!

In this rewrite, we print instead to a stringstream without a lock and then only grab the lock when we print that string out to either the console or a log file:

template <typename... Args>
static void log(const char* name, const char* color, const char* format,
                Args... args) {
    auto current_time_point = std::chrono::system_clock::now();
    std::time_t current_time =
        std::chrono::system_clock::to_time_t(current_time_point);
    char time_string[100];
    std::strftime(time_string, sizeof(time_string), datetime_format,
                  std::localtime(&current_time));
    std::stringstream ss;
    if (is_output_to_console) {
        ss << color << "[" << name << " " << time_string << "]"
                  << RESET_COLOR << " ";
    } else {
        ss << "[" << name << " " << time_string << "] ";
    }
    print_to_stream(ss, format, args...);
    std::lock_guard<std::mutex> lock(Logger::log_mutex);
    if (is_output_to_console) {
        std::cout << ss.str() << std::endl;
    } else {
        output_file << ss.str() << '\n';
    }
}

Now the log is a little more like what we would expect:

[TRACE 2024-01-01 09:42:15] This is trace message number 1
[ WARN 2024-01-01 09:42:15] 2: count = 10, What a refreshing sleep!
[ WARN 2024-01-01 09:42:15] 1: count = 10, What a refreshing sleep!
[ WARN 2024-01-01 09:42:16] 1: count = 9, What a refreshing sleep!
[ WARN 2024-01-01 09:42:16] 2: count = 9, What a refreshing sleep!
[ WARN 2024-01-01 09:42:17] 1: count = 8, What a refreshing sleep!
[ WARN 2024-01-01 09:42:17] 2: count = 8, What a refreshing sleep!
[ WARN 2024-01-01 09:42:18] 1: count = 7, What a refreshing sleep!
[ WARN 2024-01-01 09:42:18] 2: count = 7, What a refreshing sleep!
[ WARN 2024-01-01 09:42:19] 1: count = 6, What a refreshing sleep!
[ WARN 2024-01-01 09:42:19] 2: count = 6, What a refreshing sleep!
[ WARN 2024-01-01 09:42:20] 1: count = 5, What a refreshing sleep!
[ WARN 2024-01-01 09:42:20] 2: count = 5, What a refreshing sleep!
[ WARN 2024-01-01 09:42:21] 1: count = 4, What a refreshing sleep!
[ WARN 2024-01-01 09:42:21] 2: count = 4, What a refreshing sleep!
[ WARN 2024-01-01 09:42:22] 1: count = 3, What a refreshing sleep!
[ WARN 2024-01-01 09:42:22] 2: count = 3, What a refreshing sleep!
[ WARN 2024-01-01 09:42:23] 1: count = 2, What a refreshing sleep!
[ WARN 2024-01-01 09:42:23] 2: count = 2, What a refreshing sleep!
[ INFO 2024-01-01 09:42:15] roadblock says "What a refreshing sleep!"
[TRACE 2024-01-01 09:42:25] This is trace message number 2
[ WARN 2024-01-01 09:42:24] 1: count = 1, What a refreshing sleep!
[ WARN 2024-01-01 09:42:24] 2: count = 1, What a refreshing sleep!

Reconsider header-only

The usual expectation of a header-only library is that if I don't invoke anything from it, it should not add any code. However, this puts the LogType operator| and operator& code into the global namespace. Try putting just the #include of this logger into to separate files foo.cpp and bar.cpp and then create a static library from them. You'll find that you end up with two copies and a non-zero length code section for both foo and bar.

Don't use #define constants

We have std::string_view for that, which is type safe. Use that instead.

Reconsider colors

It's not necessarily a problem to make a decision on whether or not to use colors based on whether we're printing to std::cout or not, but one might reasonable want to print instead to std::cerr and may or may not want color there. I'd suggest instead having the user pass a std::ostream& and then provide an independent control for color or not.

\$\endgroup\$
2
\$\begingroup\$

Note: This isn't comprehensive but meant as addition to Edward's review above.

Bitwise Operators

There are two bitwise operators:

LogType operator|(LogType a, LogType b);
bool operator&(LogType a, LogType b);

The second one looks weird, I'd expect it to return a LogType, too. You can use that in conditional expressions, too. It's true when any bit is set, false when all are zero.

Logger Class

Your logger class is not a class that describes a type, since all "methods" are static. Effectively, that makes it a singleton, but without calling it a singleton. Even if you declared it a singleton, that would not change the fact that it introduces strong coupling, which is one reason why singleton is considered an antipattern.

Class Scope

In some places, you use Logger:: prefix, in others you don't. That's at least inconsistent. Also, using it in places where it's implied is a bit noisy to me, but that's just my preference.

Opening The Logfile

In set_output_file_name(), you are actually opening the target file twice. Also, you are not closing a previously opened file, which isn't an issue though because that is done automatically for you. That said, if opening the file fails, you don't even revert to console logging.

Intrusive Behaviour

A logger should not change the program logic. In that sense, it's okay to not throw an exception when opening the logfile fails, for example. However, when logging an error and error logging is actually enabled, your library will exit(), which is totally inacceptable. Actually, no library should call exit() or abort() except in really severe, non-recoverable cases. Logging an error, which may subsequently be handled, is not such a case.

Header-Only

I wonder, did you actually try to include this header in multiple translation units? I'd expect duplicate definitions of the class' static member objects.

Default Timestamp

In my experience, not including the timezone causes more issues than it saves space. Especially in a cloud environment, you often run in UTC, while most of the world doesn't. Including the timezone makes it unambiguous.

Naming

All macros and only macros should use UPPERCASE_ONLY identifiers. It's not immediately obvious, but there is one little exception to that rule in your code: typename T in one of the template functions.

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.