re: file-event-handlers, async loggers and dist-sink: what am I doing wrong?

[Lord-Kamina]

After my question re: having a "subsystem"/"context" name for my logs, I decided to give a whirl to just having one logger for each subsystem, so I can use the logger name.

So, I'm constructing my logger class as follows:

SpdLogger::SpdLogger (spdlog::level::level_enum const& consoleLevel) {
	spdlog::init_thread_pool(2048, 1);
	spdlog::file_event_handlers handlers;
	
	std::string msg = "logger/notice: Logging ";
	if (consoleLevel == spdlog::level::warn) {
		msg += "all notices, warnings and errors.";
	} else if (consoleLevel == spdlog::level::off) {
		msg += "disabled.";  // No-one will see this, so what's the point? :)
	} else {
		msg += fmt::format("any events of {} or higher level.", spdlog::level::to_string_view(consoleLevel));
	}
	std::clog << "logger/debug: " << msg << std::endl; // This is sending to the old logger.
	spdlog::filename_t filename = getLogFilename_new().u8string();
    handlers.before_open = [this, &msg](spdlog::filename_t) { warn(Logger::System::LOGGER, "PERFORMOUS --- {}", msg); };
    handlers.after_close = [this](spdlog::filename_t filename) { warn(Logger::System::LOGGER, "More details might be available in {}", filename); };

// 	auto stderror_graber_sink = std::make_shared<spdlog::sinks::ostream_sink_mt>();
	m_sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
	auto defaultLogger = getLogger(Logger::System::LOGGER);
	auto stdout_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
	auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(filename, 1024 * 1024 * 2, 5, true, handlers);
	m_sink->add_sink(stdout_sink);
	m_sink->add_sink(file_sink);
	spdlog::set_pattern("[%Y-%m-%d @ %T] %^%n/%l%$ -- %v");
}

Since creating loggers is theoretically cheap, but accessing the registry not so much, I decided to have my own in-class registry, in the form of an unordered map.

The way I thought it up is the following: I have a getLogger function (code attached below) that looks loggers up in its own registry and returns a shared_ptr if found. If not found, it looks it up in the spdlog registry. If It finds them, it adds it to the in-class registry and returns the pointer. If not found, it creates and registers the logger with spdlog, then it adds it to the in-class registry and returns the pointer.

It looks like this:

const loggerPtr& SpdLogger::getLogger(Logger::System loggerName) {
	try {
		return builtLoggers.at(loggerName);
	} catch (std::out_of_range const&) {
		// logger not found, did we already build it?
		auto ptr = spdlog::get(Logger::subsystemToString(loggerName));
		if (ptr) {
			builtLoggers.try_emplace(loggerName, ptr);
			return builtLoggers.at(loggerName);
		}
		else {
			auto newLogger = std::make_shared<spdlog::async_logger>(Logger::subsystemToString(loggerName), m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);
			spdlog::register_logger(newLogger);
			builtLoggers.try_emplace(loggerName, newLogger);
			return builtLoggers.at(loggerName);
		}
	}
}

One thing to note, the warn function in the constructor above is not spdlog's but rather a shortcut to a log function I wrote, as follows:

template <typename... Args>
void SpdLogger::log(Logger::System subsystem, spdlog::level::level_enum const& level, Args &&...args) {
	auto logger = getLogger(subsystem);
	logger->log(level, std::forward<Args>(args)...);
}

The problem? I get a segfault, apparently caused by the before_open file-handler (If I comment that handler out, the sink is created without issue)

Here's a backtrace of that crash:

Process 74858 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = step in
    frame #0: 0x0000000100167183 Performous`SpdLogger::SpdLogger(this=0x00007ff7bfefeda0, consoleLevel=0x00007ff7bfefed9c) at log.cc:335:84
   332 	    handlers.after_close = [&](spdlog::filename_t filename) { warn(Logger::System::LOGGER, "More details might be available in {}", filename); };
   333 	// 	auto strerror_graber_sink = std::make_shared<spdlog::sinks::ostream_sink_mt>();
   334 		auto stdout_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
-> 335 		auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(filename, 1024 * 1024 * 2, 5, true, handlers);
   336 		m_sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
   337 		m_sink->add_sink(stdout_sink);
   338 		m_sink->add_sink(file_sink);
Target 0: (Performous) stopped.
(lldb) s
Process 74858 stopped
* thread #6, stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
    frame #0: 0x0000000102ab0634 libspdlog.1.14.dylib`spdlog::sinks::sink::should_log(spdlog::level::level_enum) const + 4
libspdlog.1.14.dylib`spdlog::sinks::sink::should_log:
->  0x102ab0634 <+4>:  movl   0x8(%rdi), %eax
    0x102ab0637 <+7>:  cmpl   %esi, %eax
    0x102ab0639 <+9>:  setle  %al
    0x102ab063c <+12>: popq   %rbp
Target 0: (Performous) stopped.
(lldb) bt
* thread #6, stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
  * frame #0: 0x0000000102ab0634 libspdlog.1.14.dylib`spdlog::sinks::sink::should_log(spdlog::level::level_enum) const + 4
    frame #1: 0x0000000102ad4e99 libspdlog.1.14.dylib`spdlog::async_logger::backend_sink_it_(spdlog::details::log_msg const&) + 89
    frame #2: 0x0000000102ad644b libspdlog.1.14.dylib`spdlog::details::thread_pool::process_next_msg_() + 219
    frame #3: 0x0000000102ad6c48 libspdlog.1.14.dylib`void* std::__1::__thread_proxy[abi:v15006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::__1::function<void ()>, std::__1::function<void ()>)::$_4> >(void*) + 72
    frame #4: 0x00007ff801ea91d3 libsystem_pthread.dylib`_pthread_start + 125
    frame #5: 0x00007ff801ea4bd3 libsystem_pthread.dylib`thread_start + 15

Now, I thought maybe it could have been some sort of race-condition between creating the sink, the logger, opening the file and writing that first message to it, which is why I modified the code slightly to the version I pasted above (If you look closely, you'll see the backtrace is from a slightly different version). In this newer iteration, I decided to try to construct the dist_sink first, and construct the LOGGER logger which would be used on that event handler. After both of those are done, I construct the console and file sinks, and add them to the dist-sink using add_sink.

By doing it in this way, I manage to get the after-close text on my console, before, once again, getting a segfault.

Can you spot what the issue might be?

[tt4g]

As far as I can see there are two problems.

1. SpdLogger::getLogger() is not protected by std::mutex, so it does not look thread-safe.
2. SpdLogger::getLogger() returns std::shared_ptr&, so std::shared_ptr may become invalid if it leaves the scope of SpdLogger::getLogger().

[Lord-Kamina]

As far as I can see there are two problems.

1. SpdLogger::getLogger() is not protected by std::mutex, so it does not look thread-safe.
2. SpdLogger::getLogger() returns std::shared_ptr&, so std::shared_ptr may become invalid if it leaves the scope of SpdLogger::getLogger().

I have sidestepped the error for now, although I don't think it was related to that.
Still, it was kinda dumb on my part in retrospect.

[tt4g]

No other obvious problems are found in the code provided.
Since spdlog::sinks::sink::should_log() is crashing, it is possible that m_sink is an invalid pointer.
There is another case where the logger was disabled after calling spdlog::shutdown() (#2572), but the same problem should not occur since std::shared_ptr<spdlog::logger> is copied in builtLoggers.

[Lord-Kamina]

No other obvious problems are found in the code provided.

Since spdlog::sinks::sink::should_log() is crashing, it is possible that m_sink is an invalid pointer.

There is another case where the logger was disabled after calling spdlog::shutdown() (#2572), but the same problem should not occur since std::shared_ptr<spdlog::logger> is copied in builtLoggers.

I think the latter may have been the case, because the way I sidestepped it is, instead of adding an after-close handler, I just moved the logging call to the SpdLogger destructor, right before calling spdlog::shutdown

[tt4g]

Maybe duplicate #2113