Loggers not flushing until application exit

[ssteadman-ps]

Hello, I'm creating three loggers as so and logging a message to each:

int main()
{
    quill::Logger *logger_a = createLogger();
    quill::Logger *logger_b = createLogger();
    quill::Logger *logger_c = createLogger();

    LOG_INFO(logger_a, "hello! - logger_a");
    LOG_INFO(logger_b, "hello! - logger_b");
    LOG_INFO(logger_c, "hello! - logger_c");

    logger_a->flush_log();
    logger_b->flush_log();
    logger_c->flush_log();
    std::cout << "sleeping..." << std::endl;
    std::this_thread::sleep_for(std::chrono::milliseconds(20000));
}

The issue is that logger_a and logger_b will not log to file until the point that the application exits after 20 seconds. Logger C will log to file immediately. Checking the log files while the application is sleeping for 20 seconds, the log file created by loggers A and B will be empty, while C will contain "hello! - logger_c". Checking the log files again after the application exits, the log files created by logger a and b will become populated with their own log messages. Reversing the order of the LOG_INFO calls has no effect - logger C will still be the only logger that records to file immediately, probably as it is the last logger to be created.

Here is my createLogger function, I have tried to cut it down as best I can:

quill::Logger *createLogger() {

    if (!quill::Backend::is_running()) {
        quill::BackendOptions backend_options;
        backend_options.sleep_duration = std::chrono::nanoseconds(100);
    #ifdef _DEBUG
        backend_options.error_notifier = [](std::string const &error_message) {
            std::cout << "QUILL ERROR: " << error_message << std::endl;
        };
    #endif
        quill::Backend::start(backend_options);
    }

    // work out the log index number to add to the filename
    std::string log_index;
    int highest_index = 0;
    std::filesystem::path log_path = "D:\\samsteadman\\quill_log_test\\";
    if (std::filesystem::exists(log_path)) {
        int file_int = 0;

        // iterate through files in folder, find the highest log index number in filenames.
        for (const auto &file : std::filesystem::directory_iterator(log_path)) {
            if (file.is_regular_file()) {
                std::string file_str = file.path().filename().generic_string();
                size_t underscore_1_index = file_str.find('_');
                size_t underscore_2_index = file_str.find('_', underscore_1_index + 1);

                if (underscore_1_index != std::string::npos && underscore_2_index != std::string::npos) {
                    std::string number_str = file_str.substr(underscore_1_index + 1, underscore_2_index - underscore_1_index - 1);

                    try {
                        file_int = std::stoi(number_str);
                    } catch (const std::exception &e) {
                        file_int = 0;
                    }

                    if (file_int > highest_index) {
                        highest_index = file_int;
                    }
                }
            }
        }

        log_index = (boost::format("%03d") % (file_int + 1)).str();
    } else {
        log_index = "001";
    }

    auto file_sink = quill::Frontend::create_or_get_sink<quill::RotatingFileSink>(
        (log_path / ("PS_" + log_index + ".log")).generic_string(),
        []() {
        quill::RotatingFileSinkConfig cfg;
        cfg.set_open_mode('w');
        cfg.set_filename_append_option(quill::FilenameAppendOption::StartDateTime);
        cfg.set_rotation_time_daily("00:00");
        cfg.set_rotation_max_file_size(1024 * 1024 * 10);  // 10MB
        cfg.set_max_backup_files(100);
        return cfg;
    }());

    quill::Logger *new_logger = quill::Frontend::create_or_get_logger(
        "logger_" + log_index,
        std::move(file_sink),
        "[%(time)] [%(log_level)] [" + log_index + ":%(tags):%(caller_function)]: %(message)");

    return new_logger;
}

This is probably an issue with my implementation of creating the loggers, but can't work out how/why. I'm using quill 4.0.0 Thanks in advance!

[odygrd]

hey, I tried with a simple example on my macos laptop and could not reproduce. i will try to have a more detailed look.

You don't need to call flush on each logger, just a single flush on any logger should flush all other pending logs

In the meanwhile can you try to set fsync and tell me if it changes anything ?

      quill::RotatingFileSinkConfig cfg;
      ....
      cfg.set_do_fsync(true);

[ssteadman-ps]

Thanks for fast reply - setting fsync to true did not change anything. If it helps, I'm building using MSVC C++17, platform toolset v142.

[odygrd]

this example is working on my macos, the log_index for some reason is always 001 for me in your example. Can you try the following simplified example please and tell me if it works for you ? It will help to isolate the problem

#include "quill/Backend.h"
#include "quill/Frontend.h"
#include "quill/LogMacros.h"
#include "quill/Logger.h"
#include "quill/sinks/RotatingFileSink.h"

#include <utility>
#include <iostream>

quill::Logger *createLogger(std::string const& log_index)
{
  if (!quill::Backend::is_running())
  {
    quill::BackendOptions backend_options;
    backend_options.sleep_duration = std::chrono::nanoseconds(100);
#ifdef _DEBUG
    backend_options.error_notifier = [](std::string const &error_message) {
      std::cout << "QUILL ERROR: " << error_message << std::endl;
    };
#endif
    quill::Backend::start(backend_options);
  }

  auto file_sink = quill::Frontend::create_or_get_sink<quill::RotatingFileSink>(
    (std::string {"PS_"} + log_index + ".log"),
    []() {
      quill::RotatingFileSinkConfig cfg;
      cfg.set_open_mode('w');
      cfg.set_filename_append_option(quill::FilenameAppendOption::StartDateTime);
      cfg.set_rotation_time_daily("00:00");
      cfg.set_rotation_max_file_size(1024 * 1024 * 10);  // 10MB
      cfg.set_max_backup_files(100);
      return cfg;
    }());

  quill::Logger *new_logger = quill::Frontend::create_or_get_logger(
    "logger_" + log_index,
    std::move(file_sink),
    "[%(time)] [%(log_level)] [" + log_index + ":%(tags):%(caller_function)]: %(message)");

  return new_logger;
}

int main()
{
  quill::Logger *logger_a = createLogger("001");
  quill::Logger *logger_b = createLogger("002");
  quill::Logger *logger_c = createLogger("003");

  LOG_INFO(logger_a, "hello! - logger_a");
  LOG_INFO(logger_b, "hello! - logger_b");
  LOG_INFO(logger_c, "hello! - logger_c");

  logger_a->flush_log();
  logger_b->flush_log();
  logger_c->flush_log();
  std::cout << "sleeping..." << std::endl;
  std::this_thread::sleep_for(std::chrono::milliseconds(20000));
}

[ssteadman-ps]

This fixes the issue! I guess the issue was with my implementation of log indexing, I'll take another look at it. Strange as it seems to index the files correctly for me.

Thanks for your help and for your library, issue is clearly not yours.

[odygrd]

Just to note that calling flush on one logger will flush everything until the current timestamp of all loggers, so you do not need to call it three times. Also if you do not wish to use a logger you can just use quill::Frontend::get_valid_logger()->flush_log(); That will get the first valid logger object and call flush which is equivalent

With regards to the file creation, the file should be opened during the Sink construction in create_or_get_sink. So i would except the filesystem to see the opened file after that call

[odygrd]

when the log_index is same, this function

quill::Logger *new_logger = quill::Frontend::create_or_getlogger( "logger" + log_index, std::move(file_sink), "[%(time)] [%(log_level)] [" + log_index + ":%(tags):%(caller_function)]: %(message)");

will always try to create a logger with the same name eg logger_001

Since the logger with that name already exists it will not create a new one but return you back the same logger_001 which is bound to the same file each time ignoring the rest arguments (the new file sink)

I think the issue you are seeing might be related to this

[ssteadman-ps]

i added this print above create_or_get_sink in my original code:

std::cout << "log index is: " << log_index << std::endl;

this is the output i get:

log index is: 001
log index is: 002
log index is: 003
sleeping...

all three files are created with the correct index in their name, and the loggers are created with unique names. (logger_a = "logger_001", logger_b = "logger_002" and logger_c = "logger_003"). i can verify this by calling get_logger_name on each logger. possible that you are getting 001 every time because the directory doesn't exist on your machine?

[odygrd]

i am running it under an empty directory now , sometimes i see for example :

log index is: 001 log index is: 002 log index is: 002

can you add this line after the create_or_get_sink creation I am not sure if it helps but it ensures the filesystem sees the opened file before continuing

  while (!(std::filesystem::exists(reinterpret_cast<quill::RotatingFileSink*>(file_sink.get())->get_filename())))
  {
    std::this_thread::sleep_for(std::chrono::milliseconds{1});
  }

Also in your example should it be

log_index = (boost::format("%03d") % (highest_index + 1)).str(); instead of file_int ?

[ssteadman-ps]

Oops - yeah, it should have been highest_index, guess i was getting lucky with the order that windows was providing the filenames :P Still no change though. Loggers are all created with unique names, files are all created instantly, but the first two files will remain empty until application exit. (screenshot taken during the 20 second sleep):

[odygrd]

It seems weird if it's always working when passing the hardcoded log_index but not working when iterating the directory.

I don't have a windows environment to try it at the moment as i am away until July 10th and only have my macos laptop with me and it works there.

I can add a test on a separate branch so it runs on the windows CI in the meanwhile

[ssteadman-ps]

Testing again, I realized that the code in this comment actually didn't fix the issue, I was just still looking in the same output directory (sorry!)

https://github.com/odygrd/quill/issues/479#issuecomment-2182763440

Using this code copy pasted exactly (+ #define _CRT_SECURE_NO_WARNINGS), I still get the same issue - only logger_c will log to file immediately, the rest will log to file on application shutdown. Seems like the log indexing is unrelated to the issue here.

[odygrd]

The submitted test is passing all windows CIs.. do you mind having a look at the test, running it locally, or maybe checking programmatically the log files on your side ?

[odygrd]

I will merge this test to master but it's showing it's working as intended..

https://github.com/odygrd/quill/actions/runs/9626082157

Can this be a windows explorer issue ? Like file not refreshed for example ?

[ssteadman-ps]

Sorry for the delay over the weekend - this test also passes for me:

I will try to isolate further exactly what needs to change for it to fail

EDIT: additionally, I don't think it's an explorer issue - if i open the log files in notepad++, the first two are empty during the thread sleep while the third is populated.

[ssteadman-ps]

Updating from quill 4.0.0 to most recent master version solved the issue.

[odygrd]

Great, thanks for confirming!

There was a bug fix in v4.3.0 solving a flush bug that was introduced in v4.0.0 maybe you were seeing that

[ssteadman-ps]

That'd make sense - thanks for all your help!