C++ logger by template

Question

If the log file is not available, then output the log message to the console. Any improvement or suggestion for this implementation for the logger by the template? Any potiencial problem that I should be aware of?

#ifndef _LOGGER_HEADER__
#define _LOGGER_HEADER__
#include <iostream>
#include <string>
#include <sstream>
#include <chrono>
#include <atomic>
#include <mutex>
#include <fstream>
#include <thread>
#include <vector>
#include <iomanip>
namespace Logger
{
    enum LOG_LEVEL
    {
        LOG_LEVEL_INFO,
        LOG_LEVEL_DEBUG,
        LOG_LEVEL_ERROR,
    };

    enum LOG_MEDIA
    {
        CONSOLE,
        LOG_FILE,
    };

    extern std::atomic<bool> is_enable_log;
    extern bool is_log_file_ready;
    extern std::mutex log_mutex;
    extern enum LOG_MEDIA log_media;
    extern std::ofstream log_stream;

    std::string GetCurTime();

    void Log(std::stringstream &ss, const char* format);

    template<typename T, typename... Targs>
    void Log(std::stringstream &ss, const char* format, T value, Targs... Fargs) 
    {
        for (; *format != '\0'; format++)
        {
            if (('%' == *format) && ('#' == *(format+1)))
            {
                ss << value;
        Log(ss, format + 2, Fargs...); // recursive call
                return;
            }

            ss << *format;
        }
    }

    template<typename... Targs>
    void Log(LOG_LEVEL level, const char* file, const int line, const char* function, const char* format, Targs... Fargs)
    {
        if (!Logger::is_enable_log.load())
        {
            return;
        }

        std::stringstream ss;
        std::string file_path(file);
        auto loc = file_path.find_last_of("/\\");
        ss  << Logger::GetCurTime() << " " 
            << std::setw(11) << file_path.substr(loc+1) 
            << "[" << std::setw(4) << line << " | " << std::this_thread::get_id() <<"] <" 
            << std::setw(25) << function << "()> "; // "
        Log(ss, format, Fargs...);

DOWNGRADE_TO_COUT:
        if (Logger::LOG_FILE == Logger::log_media)
        {
            if (!is_log_file_ready)
            {
                try
                {
                    std::lock_guard<std::mutex> guard(Logger::log_mutex);
                    if (!is_log_file_ready)
                    {
                        Logger::log_stream.open("sdk.log", std::ofstream::out | std::ofstream::trunc);
                        is_log_file_ready = true;
                    }
                }
                catch (const std::exception& ex)
                {
                    std::lock_guard<std::mutex> guard(Logger::log_mutex);
                    std::cout << "encounter exception when open the file to write" << ex.what() << std::endl;
                    Logger::log_media = Logger::CONSOLE;

                    goto DOWNGRADE_TO_COUT;
                }
            }

            std::lock_guard<std::mutex> guard(Logger::log_mutex);
            Logger::log_stream << ss.str()<<std::endl;
            Logger::log_stream.flush();
        }
        else
        {
            std::lock_guard<std::mutex> guard(Logger::log_mutex);
            std::cout << "[SDK] " << ss.str();
        }
    }

    void LogDestory();
}

#if WIN32
#define LOG_INFO(format, ...)  Logger::Log(Logger::LOG_LEVEL_INFO, __FILE__, __LINE__, __FUNCTION__,  format, __VA_ARGS__)
#define LOG_DEBUG(format, ...) Logger::Log(Logger::LOG_LEVEL_DEBUG, __FILE__, __LINE__, __FUNCTION__, format, __VA_ARGS__)
#define LOG_ERROR(format, ...) Logger::Log(Logger::LOG_LEVEL_ERROR, __FILE__, __LINE__, __FUNCTION__, format, __VA_ARGS__)
#else
#define LOG_INFO(format, arg...) Logger::Log(Logger::LOG_LEVEL_INFO, __FILE__, __LINE__, __FUNCTION__,  format, ##arg)
#define LOG_DEBUG(format, arg...) Logger::Log(Logger::LOG_LEVEL_DEBUG, __FILE__, __LINE__, __FUNCTION__, format, ##arg)
#define LOG_ERROR(format, arg...) Logger::Log(Logger::LOG_LEVEL_ERROR, __FILE__, __LINE__, __FUNCTION__, format, ##arg)
#endif


#define LOG_INFO_ENTER_FUNCTION  LOG_INFO("enter function:%#", __FUNCTION__)
#define LOG_INFO_LEAVE_FUNCTION  LOG_INFO("leave function:%#", __FUNCTION__)

#endif

#include <iomanip>
#include <ctime>

std::atomic<bool> Logger::is_enable_log{ true };
bool Logger::is_log_file_ready{ false };
std::mutex Logger::log_mutex;
enum Logger::LOG_MEDIA  Logger::log_media = Logger::LOG_MEDIA::LOG_FILE;
std::ofstream Logger::log_stream;

void Logger::LogDestory()
{
    Logger::is_log_file_ready = false;
    Logger::is_enable_log.store(false);
    Logger::log_stream.close();
}

void Logger::Log(std::stringstream &ss, const char* format) 
{
    ss << format;
}

std::string Logger::GetCurTime()
{
    std::stringstream time_stream;

    std::chrono::time_point<std::chrono::system_clock> current_time_point = std::chrono::system_clock::now();
    time_t tnow = std::chrono::system_clock::to_time_t(current_time_point);

    std::time_t t = std::time(&tnow);   // get time now
    std::tm* now = std::localtime(&t);
    time_stream << (now->tm_year + 1900) << '-'
         << (now->tm_mon + 1) << '-'
         <<  now->tm_mday << " "
         <<  now->tm_hour << ":"
         <<  std::setw(2) << now->tm_min << ":"
         <<  std::setw(2) << now->tm_sec << ".";

    auto current_without_msec = std::chrono::system_clock::from_time_t(std::mktime(now));
    time_stream << std::setw(3) << std::chrono::duration_cast<std::chrono::milliseconds>(current_time_point - current_without_msec).count();

    return time_stream.str();
}


void TestLogger()
{
    std::cout << "thread speaking" << std::this_thread::get_id() << std::endl;
    for (int i = 0; i < 50; i++)
    {
        std::string str = "test";
        bool flag = true;

        LOG_INFO("%# world %# %# \n", str, 123, std::this_thread::get_id());
        LOG_INFO("this is %# a test %# %# %#\n", 1.0, flag, 3, std::this_thread::get_id());
        LOG_INFO("this is %# a test %# %# %#\n", "go out of my way", 'h', 3.1415926, std::this_thread::get_id());
    }
}

int main()
{
    std::vector<std::thread> threads;

    for (int i = 0; i < 3; i++)
    {
        threads.push_back(std::thread(TestLogger));
    }

    for (auto &thread : threads)
    {
        thread.join();
    }
    
    return 0;
}
```

Answer 1

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

Don't use function-like macros

Macros don't obey scoping rules and can't enforce typing rules. Avoid them in favor of alternatives, such as templates. See ES.31 and ES.34. In addition, your use of named variadic macro arguments as in arg... in LOG_INFO(format, arg...) is a non-standard extension.

Use standard functions to simplify your code

The GetCurTime() function is overly long and also doesn't work very well. I tried it at a few minutes past 7AM and here's how it formatted the time:

2021-8-25 7: 4: 7. 52    

That time should have been 7:04:07.052 (or better 07:04:07.052 for consistent width) and we could add some std::setfill('0') to fix that, but there's a better way by using a standard function std::put_time() instead. This rewrite of GetCurTime() is based on this answer:

std::string Logger::GetCurTime()
{
    using namespace std::chrono;
    using clock = system_clock;

    std::stringstream out;
    const auto current_time_point{clock::now()};
    const auto current_time{clock::to_time_t(current_time_point)};
    const auto current_localtime{*std::localtime(&current_time)};
    const auto current_time_since_epoch{current_time_point.time_since_epoch()};
    const auto current_milliseconds{duration_cast<milliseconds>(current_time_since_epoch).count() % 1000};
    
    out << std::put_time(&current_localtime, "%F %T") << "." << std::setw(3) << std::setfill('0') << current_milliseconds;
    return out.str();
} 

Fix the bug

If the log level is ignored, that seems like a bug to me. I think you'll find that the Log templated function does exactly that, so it's a bug that should be fixed.

Fix the spelling

I suspect that when you wrote LogDestory it really means LogDestroy. Such spelling errors, especially in interface code, looks unprofessional and can be an impediment to others understanding your code. But even simpler, see the next suggestion.

Rethink the design

As pointed out above, the LOG_LEVEL is ignored anyway, so my inclination would be to simply remove it. We also have, curiously, data and function in a namespace rather than in an object. This is a poor choice because it means that there is no clear delineation between interface (what users use) and implementation (private details on how it does what it does). Using an object would also allow the use of RAII which fixes several other problems, including the need for an explicit LogDestroy() function as mentioned above.

Use RAII to initialize an object

Assuming we want to use an object, which makes sense here, we can use RAII to eliminate a lot of errors and checking. In the existing code, the code falls back to outputting to the console if the file can't be opened. Further, it checks this every time it's called. Another way to do it is to assure that there is always (barring hardware failure, network disconnect, etc.) a valid output stream. Here's a way to do that. First, we declare two private member variables:

std::ostream* log_stream{&std::cout};
std::ofstream fileout;

Then we create a constructor:

Logger::Logger(const std::string& filename) : fileout{filename} {
    if (fileout) {
        log_stream = &fileout;
    }
}

Now if the Logger exists it has a valid ostream that either points to the file or to std::cout. Note, too, that the destructor will automatically close the file but not do anything with std::cout (although the operating system might). This eliminates the need for all of the other variables except the std::mutex since if the log exists at all, it's ready and the file (if any) is already open.

Do more thorough error checking

If the Log function is given nullptr instead of a valid format string, it will likely crash the program. Better would be to either report that or to simply ignore any such call.

Clearly separate implementation and interface

It seems as though you've already intended to do this, but a good way to separate the implementation from the interface is to use a header file and a .cpp file to contain the implementation.

Results

Here's what the refactored code looks like, using all of these suggestions:

logger.h

#ifndef _LOGGER_HEADER__
#define _LOGGER_HEADER__
#include <iostream>
#include <string>
#include <sstream>
#include <chrono>
#include <mutex>
#include <fstream>
#include <thread>
#include <iomanip>
class Logger
{
private:
    std::ostream* log_stream{&std::cout};
    std::ofstream fileout;
    std::mutex log_mutex;

    std::string GetCurTime();
    void Log(std::stringstream &ss, const char* format);

    template<typename T, typename... Targs>
    void Log(std::stringstream &ss, const char* format, T value, Targs... Fargs) {
        for (; *format != '\0'; format++) {
            if (('%' == *format) && ('#' == *(format+1))) {
                ss << value;
                Log(ss, format + 2, Fargs...); // recursive call
                return;
            }
            ss << *format;
        }
    }

public:
    Logger(const std::string& filename);
    ~Logger() = default;

    template<typename... Targs>
    void Log(const char* file, const int line, const char* function, const char* format, Targs... Fargs) {
        if (function == nullptr || format == nullptr) {
            return;
        }
        std::stringstream ss;
        std::string file_path(file);
        auto loc = file_path.find_last_of("/\\");
        ss << Logger::GetCurTime() << " " 
            << std::setw(11) << file_path.substr(loc+1) 
            << "[" << std::setw(4) << line << " | " << std::this_thread::get_id() <<"] <" 
            << std::setw(25) << function << "()> "; 
        Log(ss, format, Fargs...);
        std::lock_guard<std::mutex> guard(Logger::log_mutex);
        *log_stream << ss.str() << std::endl;
    }
};

#endif

logger.cpp

#include "logger.h"
#include <iomanip>
#include <ctime>

Logger::Logger(const std::string& filename) : fileout{filename} {
    if (fileout) {
        log_stream = &fileout;
    }
}

void Logger::Log(std::stringstream &ss, const char* format) {
    ss << format;
}

std::string Logger::GetCurTime() {
    using namespace std::chrono;
    using clock = system_clock;

    std::stringstream out;
    const auto current_time_point{clock::now()};
    const auto current_time{clock::to_time_t(current_time_point)};
    const auto current_localtime{*std::localtime(&current_time)};
    const auto current_time_since_epoch{current_time_point.time_since_epoch()};
    const auto current_milliseconds{duration_cast<milliseconds>(current_time_since_epoch).count() % 1000};
    
    out << std::put_time(&current_localtime, "%F %T") << "." << std::setw(3) << std::setfill('0') << current_milliseconds;
    return out.str();
} 

And finally, here's the reworked example code:

logtest.cpp

#include "logger.h"
#include <iostream>
#include <string>
#include <thread>
#include <vector>

Logger mylog{"sdk.log"};
// alternatively, try to create a file that can't be opened
// Logger mylog{"/root/sdk.log"};

void TestLogger() {
    std::cout << "thread speaking " << std::this_thread::get_id() << std::endl;
    const std::string str = "test";
    const bool flag = true;
    for (int i = 0; i < 50; i++) {
        mylog.Log(__FILE__, __LINE__, __FUNCTION__,  
            "%# world %# %#", str, 123, std::this_thread::get_id());
        mylog.Log(__FILE__, __LINE__, __FUNCTION__,  
            "this is %# a test %# %# %#", 1.0, flag, 3, std::this_thread::get_id());
        mylog.Log(__FILE__, __LINE__, __FUNCTION__,  
            "this is %# a test %# %# %#", "go out of my way", 'h', 3.1415926, std::this_thread::get_id());
    }
}

int main() {
    std::vector<std::thread> threads;
    for (int i = 0; i < 3; i++) {
        threads.emplace_back(std::thread(TestLogger));
    }
    for (auto &thread : threads) {
        thread.join();
    }
}

Answer 2

• I think you need #if _WIN32 not #if WIN32 to detect the platform.

• The log level doesn't seem to be used for anything?

• std::ofstream::open doesn't throw an error unless the failbit exceptions() flag is set. We either need to set the exception flag, or check is_open() instead (probably easier).

• It seems like a bad idea to hardcode the log file name in the depths of the Log function.

• It would be nice to allow the program using the log to decide what to do in case it can't open the log file, instead of hard-coding that in the log function.

• flush()ing after every message is likely to be very slow, and probably unnecessary.

• LogDestory() (spelling) is never called!

• We should probably use perfect forwarding for the template parameter pack (i.e. take the arguments as Targs&&... Fargs and then do std::forward<Targs>(Fargs)... to pass them on.

• As vvotan says, it would be best to create a class to hold the log state. The macros do force you to either pass the logger around everywhere (probably a bad idea), or use some sort of global, singleton, or service locator (probably the best option). But one global is still better than five.

Answer 3

• Having a bunch of global variables grouped by the virtue of spacing in the source file is very rarely a good idea. What you have here is a class in principle (a bunch of data plus methods), not using the class syntax for that is strange.
• Since it is not a class ,there is no notion of what is private and public. As a consequence, you have several Log functions with drastically different parameters. This makes your code difficult to follow.
• The code is not very good with separation of concerns. The code for formatting, opening files, working with file paths and writing is dumped into a single function with a strange goto in it. If you split the formatting from the output, the code will become clearer and this goto will not be needed.
• Your double-check lock is incorrect. Since the variable is non-volatile, the compiler is free to reorder the calls or optimize them away. Being extern does not help.
• It might be better to write exceptions to stderr.
• You should use ISO-8601 as your time format.It will save you a lot of trouble when other people will read it or when you decide to write a script to datamine your logs, or upload them to a database and many other situations.
• under a heavy load write/flush under a mutex might be a bottleneck