2
\$\begingroup\$

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;
}
```
\$\endgroup\$
2
  • \$\begingroup\$ Can you use source_location instead of Macros? \$\endgroup\$
    – JDługosz
    Aug 24 at 15:43
  • \$\begingroup\$ @JDługosz Thanks for your suggestion. std::source_location needs c++20 support, which's not avaliable for my compiler(i.e c++17 at most). \$\endgroup\$
    – John
    Aug 25 at 1:00
2
+50
\$\begingroup\$

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();
    }
}
\$\endgroup\$
8
  • \$\begingroup\$ I understand the appeal of such a macro, but they have a cost as I enumerated. It's up to you to decide whether the costs are worth it. In my view, they are not. \$\endgroup\$
    – Edward
    Aug 29 at 13:03
  • \$\begingroup\$ I see. Thank you so much. vvotan told me that "The double-check lock is incorrect. Since the variable is non-volatile, the compiler is free to reorder the calls or optimize them away." I have googled and talked about this advice with other people, but I still don't get an answer. I think your're a expert at C++, could you please shed some light on this matter? \$\endgroup\$
    – John
    Aug 29 at 13:11
  • \$\begingroup\$ The comment and explanation that vvotan did seem pretty good to me; I'm not sure I could do better, except perhaps with an example: godbolt.org/z/Y9P5n6qTT Note that in that simplified example, the is_log_file_ready variable is only checked once and not twice. This is what vvotan was describing. \$\endgroup\$
    – Edward
    Aug 29 at 13:42
  • \$\begingroup\$ There is a difference between my my original code snippet and your demo code. Before checking the is_log_file_ready at the second time, the thread need to acquire the mutex first. And I think ~Logger() should not be equivalent to default deconstructor. ~Logger() should try to close the opened file. How do you think about it? \$\endgroup\$
    – John
    Aug 29 at 14:01
  • \$\begingroup\$ The demo shows the effect using simplified code. Also, ~Logger() does close the file if it was opened because it automatically invokes the destructor for fileout which has the effect of closing the file. Yet another example of why RAII is so useful! \$\endgroup\$
    – Edward
    Aug 29 at 14:19
2
\$\begingroup\$
  • 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.

\$\endgroup\$
1
  • \$\begingroup\$ 1>>I think you need #if _WIN32 to detect the platform. Reply: I can't see there is either _WIN32 or WIN32 in the aforementioned code snippet indeed. 2.>>flush()ing after every message is likely to be very slow, and probably unnecessary. Reply: I am afraid that some logs may be lost if the program suddenly broke down, so I flush every message. 3.>>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()... Reply: Should I check if there is sth going wrong when writing every single message? \$\endgroup\$
    – John
    Aug 29 at 12:54
2
\$\begingroup\$
  • 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
\$\endgroup\$
12
  • \$\begingroup\$ >What you have here is a class in principle (a bunch of data plus methods), not using the class syntax for that is strange. Reply: If it's a class(i.e class Logger), then when LOG_* macros are called, I have to firstly create a instance for Logger every time. \$\endgroup\$
    – John
    Aug 23 at 3:53
  • \$\begingroup\$ It is typical to use a Singleton, such as a global variable instance of the logger. This would give you public/private and some other potential benefits for future feature growth, while being logically the same as using a namespace instead of a class. But you could have more than one instance. \$\endgroup\$
    – JDługosz
    Aug 25 at 14:35
  • \$\begingroup\$ @vvotan >"Your double-check lock is incorrect." Reply: It's to make sure only one thread to create the log file other than two or more threads. How do you think about it? \$\endgroup\$
    – John
    Aug 28 at 7:28
  • \$\begingroup\$ @vvotan >"What you have here is a class in principle (a bunch of data plus methods), not using the class syntax for that is strange." Reply: It's seems that a class could be replaced by a namespace, why I use a namespace here(and function-like macros) is because the functions by the namespace Logger is invoked by other persons, which is out of my control. \$\endgroup\$
    – John
    Aug 28 at 7:39
  • \$\begingroup\$ "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." Could you please explain that in more detail for me? \$\endgroup\$
    – John
    Aug 28 at 8:33

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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