daily_file_sink_mt, no logger in new file when new day come.

[lvhuat]

Version: 1.8.3

My setting code is below:

  auto async_file = spdlog::create_async_nb<spdlog::sinks::daily_file_sink_mt>(
      "maker", "log", 0, 0, false, 3);
  async_file->set_level(spdlog::level::info);
  spdlog::set_default_logger(async_file);
  spdlog::set_pattern("[%Y-%m-%d %H:%M:%S.%e] [%t] [%l] %v");

I use spdlog::xxx to print logger to daily file in multi thread,but:

1. when new day coming, new file was generated,but no logline in it,but my process is still running,when i restart process, it recover to print again.
2. create arg max-files not work at all,mean that no logger file was deleted until disk use out.

[lvhuat]

additional, and i found code is blocked at daily_file_sink::filename,call stack:

libpthread.so.0!__lll_lock_wait(int * futex, int private) (/build/glibc-eX1tMB/glibc-2.31/nptl/lowlevellock.c:52)
libpthread.so.0!__GI___pthread_mutex_lock(pthread_mutex_t * mutex) (/build/glibc-eX1tMB/glibc-2.31/nptl/pthread_mutex_lock.c:80)
__gthread_mutex_lock(__gthread_mutex_t * __mutex) (/usr/include/x86_64-linux-gnu/c++/7/bits/gthr-default.h:748)
std::mutex::lock(std::mutex * const this) (/usr/include/c++/7/bits/std_mutex.h:103)
std::lock_guard<std::mutex>::lock_guard(std::lock_guard<std::mutex> * const this, std::lock_guard<std::mutex>::mutex_type & __m) (/usr/include/c++/7/bits/std_mutex.h:162)
spdlog::sinks::daily_file_sink<std::mutex, spdlog::sinks::daily_filename_calculator>::filename[abi:cxx11]()(spdlog::sinks::daily_file_sink<std::mutex, spdlog::sinks::daily_filename_calculator> * const this) (/home/keto/c++/ftxdemo/src/external/spdlog/sinks/daily_file_sink.h:75)
spdlog::sinks::daily_file_sink<std::mutex, spdlog::sinks::daily_filename_calculator>::delete_old_(spdlog::sinks::daily_file_sink<std::mutex, spdlog::sinks::daily_filename_calculator> * const this) (/home/keto/c++/ftxdemo/src/external/spdlog/sinks/daily_file_sink.h:158)
spdlog::sinks::daily_file_sink<std::mutex, spdlog::sinks::daily_filename_calculator>::sink_it_(spdlog::sinks::daily_file_sink<std::mutex, spdlog::sinks::daily_filename_calculator> * const this, const spdlog::details::log_msg & msg) (/home/keto/c++/ftxdemo/src/external/spdlog/sinks/daily_file_sink.h:97)
spdlog::sinks::base_sink<std::mutex>::log(spdlog::sinks::base_sink<std::mutex> * const this, const spdlog::details::log_msg & msg) (/home/keto/c++/ftxdemo/src/external/spdlog/sinks/base_sink-inl.h:29)
spdlog::async_logger::backend_sink_it_(spdlog::async_logger * const this, const spdlog::details::log_msg & msg) (/home/keto/c++/ftxdemo/src/external/spdlog/async_logger-inl.h:63)
spdlog::details::thread_pool::process_next_msg_(spdlog::details::thread_pool * const this) (/home/keto/c++/ftxdemo/src/external/spdlog/details/thread_pool-inl.h:103)
spdlog::details::thread_pool::worker_loop_(spdlog::details::thread_pool * const this) (/home/keto/c++/ftxdemo/src/external/spdlog/details/thread_pool-inl.h:85)
spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}::operator()() const(const spdlog::details::thread_pool::<lambda()> * const __closure) (/home/keto/c++/ftxdemo/src/external/spdlog/details/thread_pool-inl.h:28)
std::__invoke_impl<void, spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}>(std::__invoke_other, spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}&&)(spdlog::details::thread_pool::<lambda()> && __f) (/usr/include/c++/7/bits/invoke.h:60)
std::__invoke<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}>(std::__invoke_result&&, (spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}&&)...)(spdlog::details::thread_pool::<lambda()> && __fn) (/usr/include/c++/7/bits/invoke.h:95)
std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}> >::_M_invoke<0ul>(std::_Index_tuple<0ul>)(std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(size_t, size_t, std::function<void()>)::<lambda()> > > * const this) (/usr/include/c++/7/thread:234)
std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}> >::operator()()(std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(size_t, size_t, std::function<void()>)::<lambda()> > > * const this) (/usr/include/c++/7/thread:243)
std::thread::_State_impl<std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(unsigned long, unsigned long, std::function<void ()>)::{lambda()#1}> > >::_M_run()(std::thread::_State_impl<std::thread::_Invoker<std::tuple<spdlog::details::thread_pool::thread_pool(size_t, size_t, std::function<void()>)::<lambda()> > > > * const this) (/usr/include/c++/7/thread:186)
libstdc++.so.6![Unknown/Just-In-Time compiled code] (Unknown Source:0)
libpthread.so.0!start_thread(void * arg) (/build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477)
libc.so.6!clone() (/build/glibc-eX1tMB/glibc-2.31/sysdeps/unix/sysv/linux/x86_64/clone.S:95)

[lvhuat]

Is that mean, sink lock twice ? :

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

void sink_it_(const details::log_msg &msg) override
{
    auto time = msg.time;
    bool should_rotate = time >= rotation_tp_;
    if (should_rotate)
    {
        auto filename = FileNameCalc::calc_filename(base_filename_, now_tm(time));
        file_helper_.open(filename, truncate_);
        rotation_tp_ = next_rotation_tp_();
    }
    memory_buf_t formatted;
    base_sink<Mutex>::formatter_->format(msg, formatted);
    file_helper_.write(formatted);

    // Do the cleaning only at the end because it might throw on failure.
    if (should_rotate && max_files_ > 0)
    {
        delete_old_();  // file rotate, execute in 
    }
}

void delete_old_()
{
    using details::os::filename_to_str;
    using details::os::remove_if_exists;

    filename_t current_file = filename();  // blocked here
    if (filenames_q_.full())
    {
        auto old_filename = std::move(filenames_q_.front());
        filenames_q_.pop_front();
        bool ok = remove_if_exists(old_filename) == 0;
        if (!ok)
        {
            filenames_q_.push_back(std::move(current_file));
            throw_spdlog_ex("Failed removing daily file " + filename_to_str(old_filename), errno);
        }
    }
    filenames_q_.push_back(std::move(current_file));
}

filename_t filename()
{
    std::lock_guard<Mutex> lock(base_sink<Mutex>::mutex_); // second aquire lock,and block
    return file_helper_.filename();
}

[lvhuat]

At same time,the rotate rule is strange.
Assume that rotate hour is 10, rotate minute is 0, and now is 2021-01-01 9:00,when process start filename log_2021_01_01 generated by FileNameCalc::calc_filename
when accross 10:00, should_rotate triggered by rotation_tp_, filename is log_2021_01_01 again, in function delete_old_,oldest file is removed,but log_2021_01_01 is push back to filenames_q_ again, it mean two filename log_2021_01_01 is in filenames_q_ at same time.

It seem that daily_filename_calculator should take rotatation config into consideration?

struct daily_filename_calculator
{
    // Create filename for the form basename.YYYY-MM-DD
    static filename_t calc_filename(const filename_t &filename, const tm &now_tm)
    {
        filename_t basename, ext;
        std::tie(basename, ext) = details::file_helper::split_by_extension(filename);
        return fmt::format(
            SPDLOG_FILENAME_T("{}_{:04d}-{:02d}-{:02d}{}"), basename, now_tm.tm_year + 1900, now_tm.tm_mon + 1, now_tm.tm_mday, ext);
    }
};

[tt4g]

I don't think your paste code is not spdlog v1.8.3 because deadlock problem already fixed #1571.
See this permalink:

spdlog/include/spdlog/sinks/daily_file_sink.h

Lines 169 to 177 in 53e1c9a

	// Delete the file N rotations ago.
	// Throw spdlog_ex on failure to delete the old file.
	void delete_old_()
	{
	using details::os::filename_to_str;
	using details::os::remove_if_exists;
	filename_t current_file = file_helper_.filename();
	if (filenames_q_.full())

daily_file_sink will perform the rotation at the specified time after the date changes.
If the file is generated and rotated on the same day, the same file name will continue to be used.
The time is not included in the file name.
Look this comment: #1908 (comment)

And you can replace the behavior because daily_filename_calculator is template parameter.

spdlog/include/spdlog/sinks/daily_file_sink.h

Line 62 in 100f300

template<typename Mutex, typename FileNameCalc = daily_filename_calculator>

[tt4g]

Another way. In spdlog v1.8.3 and after, you can use spdlog::sinks::hourly_file_sink.

[tt4g]

I wasn't aware of this, but a feature added in merge request #1847 allows you to use different file names for the same date.