Boost.Log rotation may throw boost::filesystem::filesystem_error

[debuggingbug]

Only throw on a few machine, but I think it's worth reporting.

Unhandled exception at 0x00007FF8A2CECD29 in 20230710175425258.dmp: Microsoft C++ exception: boost::filesystem::filesystem_error at memory location 0x000000A617BFF6E8.

 	KERNELBASE.dll!RaiseException�()	Unknown	Non-user code. Symbols loaded without source information.
>	VCRUNTIME140_1.dll!__FrameHandler4::CxxCallCatchBlock(_EXCEPTION_RECORD * pExcept) Line 1459	C++	Symbols loaded.
 	ntdll.dll!RcConsolidateFrames�()	Unknown	Symbols loaded.
 	hoyo_desk.exe!boost::log::v2_mt_nt6::sinks::basic_formatting_sink_frontend<char>::feed_record<boost::recursive_mutex,boost::log::v2_mt_nt6::sinks::text_file_backend>(const boost::log::v2_mt_nt6::record_view & rec, boost::recursive_mutex & backend_mutex, boost::log::v2_mt_nt6::sinks::text_file_backend & backend) Line 465	C++	Symbols loaded.
 	hoyo_desk.exe!boost::log::v2_mt_nt6::sinks::asynchronous_sink<boost::log::v2_mt_nt6::sinks::text_file_backend,boost::log::v2_mt_nt6::sinks::unbounded_fifo_queue>::run() Line 398	C++	Symbols loaded.
 	boost_thread-vc143-mt-x64-1_82.dll!00007ff87c9890ca()	Unknown	Non-user code. Binary was not built with debug information.
 	ucrtbase.dll!thread_start<unsigned int (__cdecl*)(void *),1>()	Unknown	Non-user code. Symbols loaded without source information.
 	kernel32.dll!BaseThreadInitThunk�()	Unknown	Non-user code. Symbols loaded without source information.
 	ntdll.dll!RtlUserThreadStart�()	Unknown	Non-user code. Symbols loaded without source information.

The codes:

void configLoggers(const hoyodesk::server::log::Config& config) noexcept {
    namespace fs = std::filesystem;
    auto core = logging::core::get();
    if (!config.directory.empty()) {
        if (config.is_file_backend_enabled) {
            typedef sinks::asynchronous_sink<sinks::text_file_backend> FileSink;

            fs::path log_file{config.directory / (config.stem + L".log")};
            auto file_sink = boost::make_shared<FileSink>(
                keywords::file_name = log_file,
                keywords::target_file_name = config.stem + L"_%Y%m%d_%H%M%S_%5N.log"/*,
                keywords::time_based_rotation = sinks::file::rotation_at_time_point(0, 0, 0)*/); // <--- cause problem
            file_sink->set_formatter(&formatter);
            auto backend = file_sink->locked_backend();
            backend->set_file_collector(sinks::file::make_collector(
                keywords::target = config.directory, keywords::max_size = 1024 * 1024 * 1024, // 1GB
                keywords::min_free_space = 100 * 1024 * 1024, keywords::max_files = 512));
            backend->scan_for_files();
            backend->auto_flush(true);
            backend->set_open_mode(std::ios_base::app);
            backend->set_auto_newline_mode(sinks::auto_newline_mode::always_insert);
            core->add_sink(file_sink);
        }
        else {
            DBG_ERROR("Failed to create log!");
        }
    }

    core->set_filter(Severity >= config.level);
}

[Lastique]

As any filesystem operation, rotating log files may fail, this is to be expected. From your information, it isn't clear what exactly happened, so I can't tell whether the error is legitimate.

In any case, in order to handle exceptions, you can set an exception handler to the sink frontend.

[debuggingbug]

@Lastique I already set exception handler, still can NOT catch the exception.

struct ExceptionHandler {
    typedef void result_type;

    void operator()(std::exception const& e) const noexcept {
        OutputDebugStringA(std::format("std::runtime_error: {}\n", e.what()).data());
    }
    void operator()(boost::filesystem::filesystem_error const& e) const noexcept {
        OutputDebugStringA(
            std::format("boost::filesystem::filesystem_error: {}\n", e.what()).data());
    }
};

// catch nothing
auto core = logging::core::get();
core->set_exception_handler(
    boost::log::make_exception_handler<std::exception, boost::filesystem::filesystem_error>(
        ExceptionHandler()));

// catch nothing
file_sink->set_exception_handler(
    boost::log::make_exception_handler<std::exception, boost::filesystem::filesystem_error>(
        ExceptionHandler()));

[Lastique]

If it doesn't catch then the exception is not one of the types you listed. BTW, it doesn't make sense to list std::exception first, because it will be caught before filesystem_error by the handler function object. Exceptions should be listed from the most specific ones to the most general ones, similar to how you order them in the catch blocks.

Also note that std::format is not noexcept.

Getting back to the problem, you should debug to see what the exception type is and where it is being thrown.

[debuggingbug]

Thank you! I'll improve my codes.

From minidump, I see the exception is a boost::filesystem::filesystem_error. Since the crash is on other users' machine, I can't debug.

[Lastique]

For the record, the basic_formatting_sink_frontend::feed_record function is here:

log/include/boost/log/sinks/basic_sink_frontend.hpp

Lines 436 to 480 in 28c6b1d

	template< typename BackendMutexT, typename BackendT >
	void feed_record(record_view const& rec, BackendMutexT& backend_mutex, BackendT& backend)
	{
	formatting_context* context;
	#if !defined(BOOST_LOG_NO_THREADS)
	context = m_pContext.get();
	if (!context || context->m_Version != m_Version.load(boost::memory_order_relaxed))
	{
	{
	boost::log::aux::shared_lock_guard< mutex_type > lock(this->frontend_mutex());
	context = new formatting_context(m_Version.load(boost::memory_order_relaxed), m_Locale, m_Formatter);
	}
	m_pContext.reset(context);
	}
	#else
	context = &m_Context;
	#endif
	typename formatting_context::cleanup_guard cleanup(*context);
	try
	{
	// Perform the formatting
	context->m_Formatter(rec, context->m_FormattingStream);
	context->m_FormattingStream.flush();
	// Feed the record
	BOOST_LOG_EXPR_IF_MT(boost::log::aux::exclusive_lock_guard< BackendMutexT > lock(backend_mutex);)
	backend.consume(rec, context->m_FormattedRecord);
	}
	#if !defined(BOOST_LOG_NO_THREADS)
	catch (thread_interrupted&)
	{
	throw;
	}
	#endif
	catch (...)
	{
	BOOST_LOG_EXPR_IF_MT(boost::log::aux::shared_lock_guard< mutex_type > lock(this->frontend_mutex());)
	if (this->exception_handler().empty())
	throw;
	this->exception_handler()();
	}
	}

As you can see, the function does catch all exceptions thrown by backend.consume(), so the fact that the exception keeps propagating after that means that the exception handler is not set or that it has rethrown the exception. Or that the exception fails to be caught in the first place, but then this sounds like an ABI issue (e.g. when multiple different versions of filesystem_error exist in the process, or the language runtime fails to catch the exception for some other unknown reason).

[debuggingbug]

I think I've solved this issue by adding directory to target_file_name.

 keywords::target_file_name =
                    config.directory / (config.stem + L"_%Y%m%d_%H%M%S_%5N.log")

If the directory is not specified, the new log file will be created on %ProgramFiles%\<Company>\<ProductName>, which is readonly. See the following code, m_pImpl->m_TargetStorageDir is null. filesystem::create_directories(new_file_name.parent_path()); will throw.

//! The method rotates the file
BOOST_LOG_API void text_file_backend::rotate_file()
{
    filesystem::path prev_file_name = m_pImpl->m_FileName;
    close_file();

    // Check if the file has been created in the first place
    system::error_code ec;
    filesystem::file_status status = filesystem::status(prev_file_name, ec);
    if (status.type() == filesystem::regular_file)
    {
        if (!!m_pImpl->m_TargetFileNameGenerator)
        {
            filesystem::path new_file_name = m_pImpl->m_TargetStorageDir / m_pImpl->m_TargetFileNameGenerator(m_pImpl->m_FileCounter);

            if (new_file_name != prev_file_name)
            {
                filesystem::create_directories(new_file_name.parent_path());
                move_file(prev_file_name, new_file_name);

                prev_file_name.swap(new_file_name);
            }
        }

        if (!!m_pImpl->m_pFileCollector)
            m_pImpl->m_pFileCollector->store_file(prev_file_name);
    }
}

[UMU618]

@Lastique How about specifying m_TargetStorageDir as m_StorageDir, when m_TargetStorageDir is empty?

[Lastique]

I think I've solved this issue by adding directory to target_file_name.

Good, it explains why you were getting an exception. It doesn't explain why the exception wasn't caught, though. Which means, if an exception is thrown for whatever other reason, you will have the same problem again. I'd recommend continuing debugging to fix this. Double-check that you set an exception handler for all sinks. Check if it's actually being called by setting a custom function object with console output or something instead of the one generated by make_exception_handler.

[Lastique]

@Lastique How about specifying m_TargetStorageDir as m_StorageDir, when m_TargetStorageDir is empty?

I don't like introducing this kind of non-obvious behavior. Currently, any relative paths you provide to the library are interpreted the same way as anywhere else in the process - they are relative to the current path for the process. Which means, it is probably a good idea to always provide absolute paths. But that doesn't mean it is a good idea to replace the path behind user's back.

[debuggingbug]

I don't like introducing this kind of non-obvious behavior.

When I wrote the following codes, I would naturally assume that target_file_name would be in the same directory as file_name. New log file is temporarily create in m_TargetStorageDir, and will be move to m_StorageDir. So I think this behavior do some good.

keywords::file_name = log_file,
keywords::target_file_name = config.stem + L"_%Y%m%d_%H%M%S_%5N.log"