Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Async logger crashes on shutdown during tp_.reset(). Minimal Reproducible Example provided. Does not occur in older versions. #3100

Closed
TypeDefinition opened this issue May 29, 2024 · 11 comments

Comments

@TypeDefinition
Copy link

TypeDefinition commented May 29, 2024

Hi, I am consistently crash when I call shutdown() and use async loggers.
I think it has something to do with tp_ being NULL.

The crash only occurs when running in Debug mode, and not in Release mode.
The crash occurs in the latest version of spdlog, commit c3aed4b.
I do not know exactly which commit it came from, but from my testing, an older commit which I have been using until today, da14258, does not have this issue.

You can run the example here to try it out yourself: https://github.com/TypeDefinition/spdlog_crash

This is my log class:

namespace mkr {
    class log {
    private:
        static inline std::shared_ptr<spdlog::async_logger> core_logger_ = nullptr;
        static inline std::shared_ptr<spdlog::async_logger> client_logger_ = nullptr;

    public:
        log() = delete;

        static void init(const std::string& _log_file = "./log/log.txt") {
            spdlog::init_thread_pool(8192, 1);

            auto console_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
            console_sink->set_level(spdlog::level::level_enum::trace);

            auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(_log_file, 5242880, 3, true);
            file_sink->set_level(spdlog::level::level_enum::trace);

            spdlog::sinks_init_list sink_list = {console_sink, file_sink};

            core_logger_ = std::make_shared<spdlog::async_logger>("Core Logger", sink_list.begin(), sink_list.end(), spdlog::thread_pool());
            core_logger_->set_level(spdlog::level::level_enum::trace); // Set the logger's log level to the lowest so that it does not override the sinks.
            core_logger_->flush_on(spdlog::level::level_enum::trace); // Set the logger's flush level to the lowest so that everything gets written to the file.

            client_logger_ = std::make_shared<spdlog::async_logger>("Client Logger", sink_list.begin(), sink_list.end(), spdlog::thread_pool());
            client_logger_->set_level(spdlog::level::level_enum::trace);
            client_logger_->flush_on(spdlog::level::level_enum::trace);
        }

        static void exit() {
            core_logger_->flush();
            client_logger_->flush();
            core_logger_ = nullptr;
            client_logger_ = nullptr;
            spdlog::shutdown();
        }

        inline static spdlog::async_logger* core_logger() { return core_logger_.get(); }

        inline static spdlog::async_logger* client_logger() { return client_logger_.get(); }
    };
}

#ifndef NDEBUG
    #define MKR_CORE_TRACE(...)    ::mkr::log::core_logger()->trace(__VA_ARGS__)
    #define MKR_CORE_DEBUG(...)    ::mkr::log::core_logger()->debug(__VA_ARGS__)
    #define MKR_CORE_INFO(...)     ::mkr::log::core_logger()->info(__VA_ARGS__)
    #define MKR_CORE_WARN(...)     ::mkr::log::core_logger()->warn(__VA_ARGS__)
    #define MKR_CORE_ERROR(...)    ::mkr::log::core_logger()->error(__VA_ARGS__)
    #define MKR_CORE_CRITICAL(...) ::mkr::log::core_logger()->critical(__VA_ARGS__)

    #define MKR_TRACE(...)    ::mkr::log::client_logger()->trace(__VA_ARGS__)
    #define MKR_DEBUG(...)    ::mkr::log::client_logger()->debug(__VA_ARGS__)
    #define MKR_INFO(...)     ::mkr::log::client_logger()->info(__VA_ARGS__)
    #define MKR_WARN(...)     ::mkr::log::client_logger()->warn(__VA_ARGS__)
    #define MKR_ERROR(...)    ::mkr::log::client_logger()->error(__VA_ARGS__)
    #define MKR_CRITICAL(...) ::mkr::log::client_logger()->critical(__VA_ARGS__)
#else
    #define MKR_CORE_TRACE(...)
    #define MKR_CORE_DEBUG(...)
    #define MKR_CORE_INFO(...)
    #define MKR_CORE_WARN(...)
    #define MKR_CORE_ERROR(...)
    #define MKR_CORE_CRITICAL(...)

    #define MKR_TRACE(...)
    #define MKR_DEBUG(...)
    #define MKR_INFO(...)
    #define MKR_WARN(...)
    #define MKR_ERROR(...)
    #define MKR_CRITICAL(...)
#endif

Here is my main.cpp:

#include "log/log.h"

int main() {
    mkr::log::init();
    MKR_CORE_TRACE("This is a log.");
    MKR_INFO("This is a log.");
    MKR_CORE_TRACE("This is a log.");
    MKR_INFO("This is a log.");
    MKR_CORE_TRACE("This is a log.");
    mkr::log::exit();

    return 0;
}

This is the shutdown function which it always crashes.

SPDLOG_INLINE void registry::shutdown() {
    {
        std::lock_guard<std::mutex> lock(flusher_mutex_);
        periodic_flusher_.reset();
    }

    drop_all();

    {
        std::lock_guard<std::recursive_mutex> lock(tp_mutex_);
        tp_.reset(); // <---- This line always causes a crash.
    }
}
@TypeDefinition TypeDefinition changed the title Async logger crashes on shutdown during tp_.reset(). Minimal Reproducible Example provided. Async logger crashes on shutdown during tp_.reset(). Minimal Reproducible Example provided. Does not occur in older versions. May 29, 2024
@TypeDefinition
Copy link
Author

TypeDefinition commented May 29, 2024

May I also ask if I am shutting down spdlog correctly? I assume I need to flush first, delete my loggers, then call shutdown.

@tt4g
Copy link
Contributor

tt4g commented May 29, 2024

Hi, I am consistently crash when I call shutdown() and use async loggers.
I think it has something to do with tp_ being NULL.

We cannot be sure that tp_ is NULL because there is no stacktrace.

May I also ask if I am shutting down spdlog correctly? I assume I need to flush first, delete my loggers, then call shutdown.

You are correct in that you are calling spdlog::shutdown() at the end of the application.
However, core_logger_ and client_logger_ are not registered in the spdlog registry and are not targeted for lifecycle management by spdlog::shutdown().

@tt4g
Copy link
Contributor

tt4g commented May 29, 2024

By the way, if you declare a variable in a header file with static, the variable definition will be copied each time the header file is included.
Since log.h is included in main.cpp and log.cpp, there are two different definitions and therefore two in memory storage.
In that sense, your application is causing undefined behavior in the C++ specification.
Never declare static variables in the header file.

See: https://stackoverflow.com/a/18861043

@TypeDefinition
Copy link
Author

TypeDefinition commented May 29, 2024

Hmm, I think it should be fine to initialise the static member variables in the header since they are inline. But just to confirm, I've moved the initialisation to the .cpp, but the problem persists. I've updated my example repo to use non-inline variables as well.

@tt4g
Copy link
Contributor

tt4g commented May 29, 2024

Sorry, I overlooked that your project uses C++23.

C++17 and above, static inline variables have external linkages.
However, static variables do not have external linkages.
See: https://en.cppreference.com/w/cpp/language/static

Since you are using C++23, you should leave it as static inline.

However, since CMAKE_CXX_STANDARD_REQUIRED=ON is not defined, we cannot rule out the possibility that your compiler is actually running on C++14 or earlier.
In that case, there is no external linkage in the static inline variable.

@tt4g
Copy link
Contributor

tt4g commented May 29, 2024

In any case, since tp_ is std::shared_ptr<thread_pool>.
tp_.reset() never operates an invalid pointer.
This is because it calls the std::shared_ptr<T>::reset() function.

https://github.com/gabime/spdlog/blob/c3aed4b68373955e1cc94307683d44dca1515d2b/include/spdlog/details/registry.h#L117C5-L117C38

@TypeDefinition
Copy link
Author

I am still investigating, but the issue for now seems to occur when joining the threads in the thread_pool in the thread_pool's destructor.

SPDLOG_INLINE thread_pool::~thread_pool() {
    SPDLOG_TRY {
        for (size_t i = 0; i < threads_.size(); i++) {
            post_async_msg_(async_msg(async_msg_type::terminate), async_overflow_policy::block);
        }

        for (auto &t : threads_) {
            t.join(); // <-- Issue occurs here.
        }
    }
    SPDLOG_CATCH_STD
}

@tt4g
Copy link
Contributor

tt4g commented May 29, 2024

I built the commit when the issue was opened (TypeDefinition/spdlog_crash@75b9d1cc97ce61698eb76fbae687f7b934b82e7c), but it does not reproduce on my machine.

$ cmake -S . -B build
$ cmake --build build
$ spdlog_crash
[2024-05-29 22:27:25.957] [Core Logger] [trace] This is a log.
[2024-05-29 22:27:25.957] [Client Logger] [info] This is a log.
[2024-05-29 22:27:25.957] [Core Logger] [trace] This is a log.
[2024-05-29 22:27:25.957] [Client Logger] [info] This is a log.
[2024-05-29 22:27:25.957] [Core Logger] [trace] This is a log.

I assume it is a problem with your machine.
What OS and compiler are you using?
And when you build and run TypeDefinition/spdlog_crash@75b9d1cc97ce61698eb76fbae687f7b934b82e7c, what error message do you see?

@TypeDefinition
Copy link
Author

TypeDefinition commented May 29, 2024

I am running Windows 11, using CLion, compiler is MinGW Version 11.0 w64.

I have narrowed it down to commit 1253a57, where it first started crashing.
It does not crash 1 commit earlier at cba6602.

The error I get is a segfault at stl_tree.h line 788,

static _Link_type
      _S_right(_Base_ptr __x) _GLIBCXX_NOEXCEPT
      { return static_cast<_Link_type>(__x->_M_right); }

image

Maybe I'm just unfamiliar with CLion but I don't see a stack trace anywhere.

@tt4g
Copy link
Contributor

tt4g commented May 29, 2024

Probably caused by thread_local.
This is a fatal bug of MinGW that has existed for a long time: msys2/MINGW-packages#2519
There is nothing spdlog can do about it.

@TypeDefinition
Copy link
Author

TypeDefinition commented May 29, 2024

Thanks. I can't believe that such a major bug has existed for almost 7 years and there's no plans for MinGW to fix it anytime soon. The last thing I expected was a compiler bug. Just spent an entire day scratching my head on this problem. :")

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants