after_open file-event handler firing twice for some reason?

[Lord-Kamina]

I am still in the playing around and working out kinks phase.

I got this constructor:

SpdLogger::SpdLogger (spdlog::level::level_enum const& consoleLevel) {
	spdlog::init_thread_pool(2048, 1);
	spdlog::file_event_handlers handlers;
	auto time = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
	std::string logHeader(fmt::format(
		"{0:*^80}\n"
		"{1:*^80}\n",
			fmt::format(" {} {} starting, {:%Y/%m/%d @ %H:%M:%S} ", PACKAGE, VERSION, fmt::localtime(time)),
			fmt::format(" Logging any events of level {}, or higher. ", spdlog::level::to_string_view(consoleLevel))));
	std::clog << "logger/debug: " << logHeader << std::endl;
	spdlog::filename_t filename = getLogFilename_new().u8string();
// 	auto stderror_graber_sink = std::make_shared<spdlog::sinks::ostream_sink_mt>();
	m_sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
	
	auto stdout_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();

	stdout_sink->set_color(spdlog::level::critical, logger_colors(bold_on_red)); // Error.
	stdout_sink->set_color(spdlog::level::err, logger_colors(yellow_bold)); // Warning.
	stdout_sink->set_color(spdlog::level::warn, logger_colors(green)); // Notice.
	stdout_sink->set_color(spdlog::level::info, logger_colors(white));
	stdout_sink->set_color(spdlog::level::debug, logger_colors(blue));
	stdout_sink->set_color(spdlog::level::trace, logger_colors(cyan));

	m_defaultLogger = std::make_shared<spdlog::async_logger>(Logger::subsystemToString(Logger::System::LOGGER), m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);

	handlers.after_open = [this, logHeader](spdlog::filename_t filename, std::FILE *fstream) {
		std::clog << "logger/debug: will call writeLogHeader()" << std::endl;
		writeLogHeader(filename, fstream, logHeader);
	};

	m_sink->add_sink(stdout_sink);
	auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(filename, 1024 * 1024 * 2, 5, true, handlers);
	m_sink->add_sink(file_sink);
	m_sink->set_pattern("[%^%n / %l%$ @ %T]::: %v");
}

And here's writeLogHeader():

void SpdLogger::writeLogHeader(spdlog::filename_t filename, std::FILE* fd, std::string header) {
	if (fd == nullptr) {
		error(Logger::System::LOGGER, "Unable to write to logfile at {}, invalid fstream.", filename);
		return;
		}
	header.append("\n");
	int ret = std::fputs(header.c_str(), fd);
	m_sink->sinks().back()->set_level(spdlog::level::critical);
	notice(Logger::System::LOGGER, header);
	m_sink->flush();
	m_sink->sinks().back()->set_level(spdlog::level::trace);
	if (ret == EOF) {
		error(Logger::System::LOGGER, "Unable to write to logfile at {}, error: {}", filename, std::strerror(errno));
		return;
	}
}

This function results in "logger/debug: will call writeLogHeader()" being printed twice to the console: One with the default spdlog format, and then once with my own custom format.

And then, it's also appended to my log file, which will look like this:

******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/11 @ 10:12:33 ********
**************** Logging any events of level DEBUG, or higher. *****************

[LOGGER / NOTICE @ 10:12:33]::: ******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/11 @ 10:12:33 ********
**************** Logging any events of level DEBUG, or higher. *****************

P.S. both the flush() and the set_level calls in writeLogHeader were put in there trying to work around the issue, and neither seems to have worked.

[tt4g]

The fourth argument rotate_on_open is true, so it is opened once and then reopened in a rotation operation.

First open in constructor:

spdlog/include/spdlog/sinks/rotating_file_sink-inl.h

Lines 44 to 49 in e593f66

	file_helper_.open(calc_filename(base_filename_, 0));
	current_size_ = file_helper_.size(); // expensive. called only once
	if (rotate_on_open && current_size_ > 0) {
	rotate_();
	current_size_ = 0;
	}

rotate_() closes first and reopens after rotation:

spdlog/include/spdlog/sinks/rotating_file_sink-inl.h

Lines 102 to 107 in e593f66

	template <typename Mutex>
	SPDLOG_INLINE void rotating_file_sink<Mutex>::rotate_() {
	using details::os::filename_to_str;
	using details::os::path_exists;
	file_helper_.close();

spdlog/include/spdlog/sinks/rotating_file_sink-inl.h

Lines 130 to 131 in e593f66

	file_helper_.reopen(true);
	}

[Lord-Kamina]

I've been trying to work around this in a number of ways, because I don't want the header to be duplicated in the logfile, but I want it also on the console... of course, one option would be to create an initial logger that outputs ONLY to the logfile for just the header, but that feels hacky.

After your last comment @tt4g, I decided to move the console logging out of the file-open handler, to be one of the last things in the SpdLogger constructor. However, it's become apparent that there is an issue here, either some data race, or the way it's implemented.

Here's the updated constructor:

SpdLogger::SpdLogger (spdlog::level::level_enum const& consoleLevel) {
	Profiler prof("spdLogger-init");
	spdlog::init_thread_pool(2048, 1);
	spdlog::file_event_handlers handlers;
	auto time = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
	std::string logHeader(fmt::format(
		"{0:*^80}\n"
		"{1:*^80}\n",
			fmt::format(" {} {} starting, {:%Y/%m/%d @ %H:%M:%S} ", PACKAGE, VERSION, fmt::localtime(time)),
			fmt::format(" Logging any events of level {}, or higher. ", spdlog::level::to_string_view(consoleLevel))));
	std::clog << "logger/debug: " << logHeader << std::endl;
	spdlog::filename_t filename = getLogFilename_new().u8string();
// 	auto stderror_graber_sink = std::make_shared<spdlog::sinks::ostream_sink_mt>();
	m_sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
	
	auto stdout_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();

	stdout_sink->set_color(spdlog::level::critical, logger_colors(bold_on_red)); // Error.
	stdout_sink->set_color(spdlog::level::err, logger_colors(yellow_bold)); // Warning.
	stdout_sink->set_color(spdlog::level::warn, logger_colors(green)); // Notice.
	stdout_sink->set_color(spdlog::level::info, logger_colors(white));
	stdout_sink->set_color(spdlog::level::debug, logger_colors(blue));
	stdout_sink->set_color(spdlog::level::trace, logger_colors(cyan));
	m_defaultLogger = std::make_shared<spdlog::async_logger>(Logger::subsystemToString(Logger::System::LOGGER), m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);

	handlers.after_open = [this, logHeader](spdlog::filename_t filename, std::FILE *fstream) {
		std::clog << "logger/debug: will call writeLogHeader()" << std::endl;
		writeLogHeader(filename, fstream, logHeader);
	};
// 	handlers.after_close = [this](spdlog::filename_t filename) { warn(Logger::System::LOGGER, "More details might be available in {}", filename); };
	auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(filename, 1024 * 1024 * 2, 5, true, handlers);
	file_sink->set_level(spdlog::level::off);
	m_sink->add_sink(file_sink);
	m_sink->add_sink(stdout_sink);
	m_sink->set_pattern("[%T]:::%^%n / %l%$::: %v");
	const std::string _fl = std::string{spdlog::level::to_string_view(file_sink->level()).begin(),spdlog::level::to_string_view(file_sink->level()).end()};
	const std::string _sl = std::string{spdlog::level::to_string_view(stdout_sink->level()).begin(), spdlog::level::to_string_view(stdout_sink->level()).end()};
	const std::string file_level = std::string{_fl};
	const std::string stdout_level = std::string{_sl};
	std::clog << "logger/debug: file_sink->level(): " << file_level << std::endl;
	std::clog << "logger/debug: stdout_sink->level(): " << stdout_level << std::endl;
	notice(Logger::System::LOGGER, logHeader);
	m_sink->flush();
	file_sink->set_level(spdlog::level::debug);
}

What is happening now is that the header message is still written to both the console and the file (twice to the file), even though the level of the file sink should be level::off when that line gets logged to the console.

That could possibly be abscribed to the async logging of course, but there's also the fact that all the old log files are also being opened due to the rotation, and this means that they get the header appended at the end.

[tt4g]

The situation is so complex that the cause cannot be determined by looking only at the SpdLogger constructor code.

I think it is because log level filtering by sink is an asynchronous operation when using async_logger.
However, the following behavior does not appear to be due to async_logger.
It sounds like a state race is happening because you are writing to the same file with multiple file_sinks.

but there's also the fact that all the old log files are also being opened due to the rotation, and this means that they get the header appended at the end.

[Lord-Kamina]

I think there is a race between modifying the level and writing to the file, but there is only a single file sink, and that goes inside the dist sink (which is a class member of SpdLogger), which is what everything will use to access the file eventually. The only access to the file sink other than through the dist_sink is to temporarily set it to level::off

I wonder... might this be worked around by allowing sinks to be set to a different level at construction time?

[tt4g]

If the headers are being written from after_open, then maybe the problem is in the after_open callback?
The writeLogHeader() being called from it is calling error() and notice(), but we cannot guess the cause because we do not know what they are.
And since after_open is not called at sink build time, I don't think it is relevant here.

[tt4g]

I just realized my oversight.

Calling m_sink->flush(); inside SpdLogger::writeLogHeader() should thrown exception.
Because although the rotation operation (which calls the after_open callback) is performed inside rotating_file_sink::sink_it_(),
This function is called from base_sink::log().
Since base_sink::log() and base_sink::flush() are locked by the same std::mutex,
Calling base_sink::flush() inside rotating_file_sink::sink_it_() will cause lock conflicts.

• spdlog/include/spdlog/sinks/base_sink-inl.h

  Lines 25 to 35 in e593f66

  	template <typename Mutex>
  	void SPDLOG_INLINE spdlog::sinks::base_sink<Mutex>::log(const details::log_msg &msg) {
  	std::lock_guard<Mutex> lock(mutex_);
  	sink_it_(msg);
  	}
  	template <typename Mutex>
  	void SPDLOG_INLINE spdlog::sinks::base_sink<Mutex>::flush() {
  	std::lock_guard<Mutex> lock(mutex_);
  	flush_();
  	}

• spdlog/include/spdlog/sinks/rotating_file_sink-inl.h

  Lines 72 to 90 in e593f66

  	template <typename Mutex>
  	SPDLOG_INLINE void rotating_file_sink<Mutex>::sink_it_(const details::log_msg &msg) {
  	memory_buf_t formatted;
  	base_sink<Mutex>::formatter_->format(msg, formatted);
  	auto new_size = current_size_ + formatted.size();
  	// rotate if the new estimated file size exceeds max size.
  	// rotate only if the real size > 0 to better deal with full disk (see issue #2261).
  	// we only check the real size when new_size > max_size_ because it is relatively expensive.
  	if (new_size > max_size_) {
  	file_helper_.flush();
  	if (file_helper_.size() > 0) {
  	rotate_();
  	new_size = formatted.size();
  	}
  	}
  	file_helper_.write(formatted);
  	current_size_ = new_size;
  	}

Suppose an exception is thrown due to a lock conflict,
It should be handled in the following catch and msg.source should be printed in the spdlog error handler (default behavior https://github.com/gabime/spdlog/wiki/Error-handling).

spdlog/include/spdlog/async_logger-inl.h

Lines 63 to 67 in e593f66

	for (auto &sink : sinks_) {
	if (sink->should_log(msg.level)) {
	SPDLOG_TRY { sink->log(msg); }
	SPDLOG_LOGGER_CATCH(msg.source)
	}

Since spdlog's sink is not guaranteed to be reentrant, it is best not to call sink's logging and flush methods from callbacks.
If you really want to do those operations, call the internal API that is called after the lock is acquired.

[Lord-Kamina]

If the headers are being written from after_open, then maybe the problem is in the after_open callback?

The writeLogHeader() being called from it is calling error() and notice(), but we cannot guess the cause because we do not know what they are.

And since after_open is not called at sink build time, I don't think it is relevant here.

Those methods are just shortcuts to log(spdlog::level::error) and log(spdlog::level::warn) respectively.

[Lord-Kamina]

I just realized my oversight.

Calling m_sink->flush(); inside SpdLogger::writeLogHeader() should thrown exception.

Because although the rotation operation (which calls the after_open callback) is performed inside rotating_file_sink::sink_it_(),

This function is called from base_sink::log().

Since base_sink::log() and base_sink::flush() are locked by the same std::mutex,

Calling base_sink::flush() inside rotating_file_sink::sink_it_() will cause lock conflicts.

• spdlog/include/spdlog/sinks/base_sink-inl.h

  Lines 25 to 35 in e593f66

  	template <typename Mutex>
  	void SPDLOG_INLINE spdlog::sinks::base_sink<Mutex>::log(const details::log_msg &msg) {
  	std::lock_guard<Mutex> lock(mutex_);
  	sink_it_(msg);
  	}
  	template <typename Mutex>
  	void SPDLOG_INLINE spdlog::sinks::base_sink<Mutex>::flush() {
  	std::lock_guard<Mutex> lock(mutex_);
  	flush_();
  	}

• spdlog/include/spdlog/sinks/rotating_file_sink-inl.h

  Lines 72 to 90 in e593f66

  	template <typename Mutex>
  	SPDLOG_INLINE void rotating_file_sink<Mutex>::sink_it_(const details::log_msg &msg) {
  	memory_buf_t formatted;
  	base_sink<Mutex>::formatter_->format(msg, formatted);
  	auto new_size = current_size_ + formatted.size();
  	// rotate if the new estimated file size exceeds max size.
  	// rotate only if the real size > 0 to better deal with full disk (see issue #2261).
  	// we only check the real size when new_size > max_size_ because it is relatively expensive.
  	if (new_size > max_size_) {
  	file_helper_.flush();
  	if (file_helper_.size() > 0) {
  	rotate_();
  	new_size = formatted.size();
  	}
  	}
  	file_helper_.write(formatted);
  	current_size_ = new_size;
  	}

Suppose an exception is thrown due to a lock conflict,

It should be handled in the following catch and msg.source should be printed in the spdlog error handler (default behavior https://github.com/gabime/spdlog/wiki/Error-handling).

spdlog/include/spdlog/async_logger-inl.h

Lines 63 to 67 in e593f66

	for (auto &sink : sinks_) {
	if (sink->should_log(msg.level)) {
	SPDLOG_TRY { sink->log(msg); }
	SPDLOG_LOGGER_CATCH(msg.source)
	}

Since spdlog's sink is not guaranteed to be reentrant, it is best not to call sink's logging and flush methods from callbacks.

If you really want to do those operations, call the internal API that is called after the lock is acquired.

I don't really want to flush there, I added it to see if it made any difference.

[tt4g]

I don't really want to flush there, I added it to see if it made any difference.

Then please remove the m_sink->flush(); in SpdLogger::writeLogHeader().

I don't think this leaves any questions, but what is the reason for not closing?

[Lord-Kamina]

I don't really want to flush there, I added it to see if it made any difference.

Then please remove the m_sink->flush(); in SpdLogger::writeLogHeader().

I don't think this leaves any questions, but what is the reason for not closing?

I am sorry, actually, because I should have posted the entire code here, but when that was posted, the flush had already been removed from writeLogHeader. I had moved that call (along with the call to notice) to the constructor, and I'm getting the behavior described above, with which I see two problems.

1. Each log begins with:

******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/14 @ 15:18:16 ********
**************** Logging any events of level DEBUG, or higher. *****************
``` (This is from std::fputs in `writeLogHeader`)

[15:18:16]:::LOGGER / NOTICE::: ******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/14 @ 15:18:16 ********
**************** Logging any events of level DEBUG, or higher. *****************
``` (this is from notice in the SpdLogger constructor, despite the file-sink having been set to `level::off` earlier in the same constructor; this likely due to a race condition because changing the sink level is not using any locks)

And then,

2. Upon rotation, each file gets that header appended again at the end (although for some reason it seems to be happening only on the first rotation, which is kinda weird IMO), meaning there's probably a bug in the way rotating_file_sink interacts with the file-open/close handlers.

Here's how the log from the next-to-last run is currently looking like:

******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/15 @ 11:59:34 ********
**************** Logging any events of level DEBUG, or higher. *****************

[11:59:34]:::LOGGER / NOTICE::: ******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/15 @ 11:59:34 ********
**************** Logging any events of level DEBUG, or higher. *****************

[11:59:34]:::LOGGER / NOTICE::: Testing whether spdlog works? true
[11:59:34]:::LOGGER / NOTICE::: And does it work without a parameter?
[11:59:34]:::SONGS / NOTICE::: And does it work without a parameter?
[11:59:34]:::AUDIO / NOTICE::: And does it work without a parameter?
[11:59:34]:::CACHE / NOTICE::: And does it work without a parameter?
[11:59:34]:::GAME / NOTICE::: And does it work without a parameter?
[11:59:34]:::SONGPARSER / NOTICE::: And does it work without a parameter?
[11:59:34]:::TEXT / NOTICE::: And does it work without a parameter?
[11:59:34]:::WEBCAM / NOTICE::: And does it work without a parameter?
[11:59:42]:::LOGGER / WARNING::: More details might be available in /Users/Koji/Library/Caches/Performous/infolog-new.txt
******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/15 @ 12:00:06 ********
**************** Logging any events of level DEBUG, or higher. *****************

[gabime]

Note you construct the file sink with rotate_on_open=true which might lead to this behavior

[Lord-Kamina]

Note you construct the file sink with rotate_on_open=true which might lead to this behavior

I understand that is the direct cause of the behavior, but my point is that it shouldn't behave like that.
i.e., if one of the chief intended purposes of having on-file-open handlers is to write a header to a log file, they shouldn't get triggered when they're opened for rotation.

Or, come to think of it... why does the file even need to be opened for rotating it? Shouldn't it be possible to rotate it just by checking if the filename already exists?

[Lord-Kamina]

Also, I think it should be possible to change the initial level of a sink, or reading/modifying the level should use a mutex, or both.

The way spdlog is now, even if I comment-out the line defining the handler, it's evident there is a data race in should_log.

This:

SpdLogger::SpdLogger (spdlog::level::level_enum const& consoleLevel) {
	Profiler prof("spdLogger-init");
	spdlog::init_thread_pool(2048, 1);
	spdlog::file_event_handlers handlers;
	auto time = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
	std::string logHeader(fmt::format(
		"{0:*^80}\n"
		"{1:*^80}\n",
			fmt::format(" {} {} starting, {:%Y/%m/%d @ %H:%M:%S} ", PACKAGE, VERSION, fmt::localtime(time)),
			fmt::format(" Logging any events of level {}, or higher. ", spdlog::level::to_string_view(consoleLevel))));
	std::clog << "logger/debug: " << logHeader << std::endl;
	spdlog::filename_t filename = getLogFilename_new().u8string();
	m_sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
	
	auto stdout_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();

	stdout_sink->set_color(spdlog::level::critical, logger_colors(bold_on_red)); // Error.
	stdout_sink->set_color(spdlog::level::err, logger_colors(yellow_bold)); // Warning.
	stdout_sink->set_color(spdlog::level::warn, logger_colors(green)); // Notice.
	stdout_sink->set_color(spdlog::level::info, logger_colors(white));
	stdout_sink->set_color(spdlog::level::debug, logger_colors(blue));
	stdout_sink->set_color(spdlog::level::trace, logger_colors(cyan));
	m_defaultLogger = std::make_shared<spdlog::async_logger>(Logger::subsystemToString(Logger::System::LOGGER), m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);
	auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(filename, 1024 * 1024 * 2, 5, true, handlers);
	file_sink->set_level(spdlog::level::off);
	m_sink->add_sink(file_sink);
	m_sink->add_sink(stdout_sink);
	m_sink->set_pattern("[%T]:::%^%n / %l%$::: %v");
	const std::string _fl = std::string{spdlog::level::to_string_view(file_sink->level()).begin(),spdlog::level::to_string_view(file_sink->level()).end()};
	const std::string _sl = std::string{spdlog::level::to_string_view(stdout_sink->level()).begin(), spdlog::level::to_string_view(stdout_sink->level()).end()};
	const std::string file_level = std::string{_fl};
	const std::string stdout_level = std::string{_sl};
	std::clog << "logger/debug: file_sink->level(): " << file_level << std::endl;
	std::clog << "logger/debug: stdout_sink->level(): " << stdout_level << std::endl;
	notice(Logger::System::LOGGER, logHeader);
	file_sink->set_level(spdlog::level::debug);
}

produces this on the console:

$ ./out/Performous-1.3.1-40-gcb369ffb3/Performous.app/Contents/MacOS/Performous -l debug
logger/notice: Logging any events of debug or higher level. Log file: /Users/Koji/Library/Caches/Performous/infolog.txt
stderr/info: Standard error output redirected here
logger/debug: ******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/15 @ 16:33:21 ********
**************** Logging any events of level DEBUG, or higher. *****************

logger/debug: file_sink->level(): OFF
logger/debug: stdout_sink->level(): TRACE
[16:33:21]:::LOGGER / NOTICE::: ******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/15 @ 16:33:21 ********
**************** Logging any events of level DEBUG, or higher. *****************

[16:33:21]:::LOGGER / NOTICE::: Testing whether spdlog works? true

And the log-file begins with

[16:33:21]:::LOGGER / NOTICE::: ******** Performous 1.3.1-40-gcb369ffb3 starting, 2024/10/15 @ 16:33:21 ********
**************** Logging any events of level DEBUG, or higher. *****************

despite the file_sink being set to level::off

[tt4g]

i.e., if one of the chief intended purposes of having on-file-open handlers is to write a header to a log file, they shouldn't get triggered when they're opened for rotation.

Or, come to think of it... why does the file even need to be opened for rotating it? Shouldn't it be possible to rotate it just by checking if the filename already exists?

Assuming that some users are doing flock() like operations in after_open, if not closed while rotating (renaming), there will be a problem.

despite the file_sink being set to level::off

As already answered, this is an expected behavior that occurs because of the use of async_logger (level change is a synchronous operation, log writing is an asynchronous operation).

[tt4g]

I don't know the conditions under which you write headers to the log, but if you assume it is when a new log file is created, then simply writing the headers only when you get the size of the file in the after_open callback should solve the whole problem.