Daily Logger - daily rotations and confusing target file names

[onavratil-monetplus]

I was experimenting with daily filename rotation, like this:

        // Prepare sink
        std::shared_ptr<spdlog::sinks::sink> targetSink;
        if (loggerConfig.daily){
            Logger::info("Creating daily logger sink.");
            targetSink = std::make_shared<spdlog::sinks::daily_file_sink_mt>(loggerConfig.fileName, loggerConfig.hours, loggerConfig.minutes, false, loggerConfig.maxFiles);
        }
        else{
            Logger::info("Creating stdout logger sink.");
            targetSink = std::make_shared<spdlog::sinks::stdout_sink_mt>();
        }

        //Prepare logger
        std::shared_ptr<spdlog::logger> targetLogger; 
        if(loggerConfig.async){
            Logger::info("Creating async logger.");
            spdlog::init_thread_pool(loggerConfig.queueItems, loggerConfig.threadCount);
            targetLogger = std::make_shared<spdlog::async_logger>("async_logger", targetSink, spdlog::thread_pool());
        }
        else {
            Logger::info("Creating sync logger.");
            targetLogger = std::make_shared<spdlog::logger>("sync_logger", targetSink);
        }
        targetLogger->set_pattern(Logger::PATTERN);
        spdlog::set_default_logger(targetLogger);

I wanted to test the rotation, i.e. I set the hour and minute to like ~1-2min ahead, started my app, poked it to produce some logs, and expected to see new file created in the log folder in a few mins.

Which did not happen.

The logger constructor calculates the initial log filename based on current date/time

        auto now = log_clock::now();
        auto filename = FileNameCalc::calc_filename(base_filename_, now_tm(now));

Then, when rotation occurs, this happens

        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_();
        }

Once again, the filename is determined by the log entry count, and the date remains unchanged.

This is kind of tricky to figure out, and even harder to debug. I suggest at least to make a documentation entry.

Moreover, in extreme cases, this may lead to unexpected/undefined behavior:

• I suspect the open file queue will now contain the filename twice, and thus setting max_files may cause deletion of an extra file (needs verification)
• Lets say hours and minutes are set to noon, 12:00. Consider now that the program logs very sparsely into this sink.
  • Some log event on 2025-01-01T13:00 will create the 2025-01-01.txt log file. The rotation_tp_ will be 2025-01-02T12:00
  • No log event will appear between 2025-01-02T12:00 and 2025-01-02T23:59
  • Another log even appears 2025-01-03T00:30. This is clearly after rotation_tp_ and will cause creation of a new file.
  • However, the date in the filename will be derived from the event appearance time, which is not 01-02 but 01-03
  • The target filename for the log is ambiguous, depending on whether some log entry was produces between the rotation hour:minute of the previous day or not, it will either be in today's or yesterdays log file
  • This will get worse as hour:minute grows towards 23:59 (1 minute without logging is not that exotic)
  • It may cause confusion when reading logs

[gabime]

The daily logger has indeed some issues. The queue stuff for example, which means that after app restart/crash, the queue would
be empty. Improvements/suggestions/PR are welcome. Breaking changes are also ok since we could have a new daily sink v2 and deprecate the current. For example I dont think it should support max file count as it complicates greatly the implementation and it is really the job of some cron job.