Changing log output file on the fly for a given logger?

[rexkerr]

I'm working on an application where I want to be able to change the output log file for a named log on the fly to a new file in a different location on the disk when a given event occurs. I want client logging code to 1) not need to know or care that the event has occurred, and 2) be able to safely cache the log pointer so that they don't have to search the registry every time they need to log a message since it's performance sensitive code.

I'm currently experimenting with a demo program and it seems to be working, but I'm afraid that I'm "getting lucky" and that the cached raw pointer address just happens to be the same after this call:

void new_log()
{
    auto constexpr logname = "eventlog";
    quill::remove_logger(quill::get_logger(logname));
    quill::flush();
    auto const log= quill::create_logger(logname, quill::file_handler(generate_filename(),
            []() {
                quill::FileHandlerConfig cfg;
                cfg.set_open_mode('w');
                cfg.set_append_to_filename(quill::FilenameAppend::StartDateTime);
                return cfg;
            }()));
}

I then want to use it something like this:

    // I'm going to get the log in advance to simulate caching it and then using it after calls to new_log
    auto log= quill::get_logger("eventlog");

    new_log();  // this would be called elsewhere, so I can't just say   log = new_log
    LOG_INFO(log, "This should go to log 0");

    new_log();
    LOG_INFO(log, "This should go to log 1");
    LOG_INFO(log, "This should also go to log 1");

    new_log();
    LOG_INFO(log, "This should go to log 2");
    LOG_INFO(log, "This should also go to log 2");

Looking at the code I'm actually surprised that this is working as it looks to me like the invalidate flag is set on remove_log, which will cause the background worker to eventually remove the log from the map, but in my case I'm "getting lucky" in that my new_log function isn't getting interrupted so the worker isn't getting around to the cleanup, but I still don't see how it ended up that the raw pointer from get_log can point to the new object -- I'm missing something.

If what I'm missing is something that guarantees this pattern will work, then I'll be very happy, but assuming that this is NOT the right way to change the output file on the fly, is there a supported method to do this? I've looked at trying to use the rolling file logger and setting it to not automatically roll, but 1) I don't see a way to explicitly force it to roll, and 2) I don't see a way to set an arbitrary filename.

It seems that I can write my own handler based on rolling file logger, but I don't want to have to maintain that and would prefer a pre-baked solution.

Thanks!

[rexkerr]

...to partially answer my own question, creating an intermediate throwaway logger in my new_log function between the flush and create_logger causes the pointer to no longer be the same, so this example only works by accident, confirming my concern w/ the above usage pattern -- so I guess my remaining question is whether there's a way to change the output filename on a handler, assign a new handler, or otherwise redirect the output without having to create a whole new logger so that any cached logger pointers continue to be valid.

On a related note, why does get_logger return a raw pointer as opposed to a shared pointer? If it were to return a shared_ptr then I could cache it was a weak pointer and check its validity that way faster than iterating through the registry and comparing names.

[odygrd]

Hey, the example you posted won't work. remove_logger removes the logger async in the background thread, create_logger gives you the existing logger if it exists and if not it creates it. You do not get notified when the backend thread removed the logger to call create_logger() to get the logger to the new output, it might still return the old logger instance.

It is not possible to change the Handlers once a Logger is created.

I am not sure exactly what is the condition that will trigger the log output change.
If you know your outputs in advance and the condition is in the log statement or in the metadata, then you can create the logger with all Handlers outputs from the beginning and then use a Filter for each output.

https://github.com/odygrd/quill/blob/master/examples/example_filters.cpp

The other solution would be to create a Logger per output and an abstraction and ask your client to call get_logger() each time

class SelectLogger
{
public:
SelectLogger()
{
   // create _output_logger_a _output_logger_b etc
}

Logger* get_logger() const { return _current_logger; }
void use_output_a()  { _current_logger = _output_logger_a; }
void use_output_b()  { _current_logger = _output_logger_b; }

private:
Logger* _current_logger;
Logger* _output_logger_a;
Logger* _output_logger_b;
}

[rexkerr]

Thank you. Yes, I was coming to the same conclusion yesterday that while it was working, it should not -- and was able to force a failure by adding some allocations so that the pointer moved.

I am not sure exactly what is the condition that will trigger the log output change.
If you know your outputs in advance and the condition is in the log statement or in the metadata, then you can create the logger with all Handlers outputs from the beginning and then use a Filter for each output.

At a high level, in addition to a global system log I want a log file for events related to the data being created that is part of the data bundle -- where the end user can create an arbitrary number of datasets during a system run and I don't know the output locations in advance. Ideally I'll be able to pass a logger object in to the code that will be logging these events (and can therefore create a new one for every dataset), but I'm not certain whether that'll always be true, thus my reason for wanting to be able to continue to use an existing log object even though it's pointing to a different output file.

I ended up writing a custom handler based on the code in the rotating log handler. I originally wrote it in the quill namespace in the repo with the thought that I might create a PR if you're interested in adding it to the library -- I'm debating whether my use case is generic enough to submit something like this (once I have time to write unit tests, update the documentation, write the factory function, optimize the mutex scope, etc, to make it PR ready) or whether I'll be adding more functionality to the class for my specific use case, in which case it won't be generic enough to share here so I'd move it out into my client code.

Here's what I ended up with, which seems to be working well -- do you think it would be generic enough to include in the library?

In short, the class is derived from FileHander and has a member path variable that starts out empty. On every write, if the new requested path is set it closes the old file and starts a new one.

#pragma once

#include "quill/detail/misc/Attributes.h" // for QUILL_ATTRIBUTE_COLD, QUIL...
#include "quill/handlers/FileHandler.h"   // for FileHandler

#include <mutex>

namespace quill
{

/**
 * The RedirectableFileHandlerConfig class holds the configuration options for the RedirectableFileHandler
 */
class RedirectableFileHandlerConfig : public FileHandlerConfig
{
    // placeholder for extension
};

/**
 * @brief The RedirectableFileHandler class
 */
class RedirectableFileHandler : public FileHandler
{
public:
  /**
   * @brief Constructor.
   *
   * Creates a new instance of the RedirectableFileHandler class.
   *
   * @param filename The base file name to be used for logs.
   * @param start_time start time
   * @param config The handler configuration.
   * @param file_event_notifier file event notifier
   */
  RedirectableFileHandler(fs::path const& filename, RedirectableFileHandlerConfig const& config,
                      FileEventNotifier file_event_notifier);

  /**
   * @brief Destructor.
   *
   * Destroys the RedirectableFileHandler object.
   */
  ~RedirectableFileHandler() override = default;


  void set_requested_filename(quill::fs::path const& requested_filename) noexcept
  {
      std::lock_guard lock{_mutex};
      _requested_filename = requested_filename;
  }

  /**
   * @brief Write a formatted log message to the stream.
   *
   * This function writes a formatted log message to the file stream associated with the handler.
   *
   * @param formatted_log_message The formatted log message to write.
   * @param log_event The log event associated with the message.
   */
  QUILL_ATTRIBUTE_HOT void write(fmt_buffer_t const& formatted_log_message,
                                 TransitEvent const& log_event) override;

private:
  std::mutex _mutex;
  quill::fs::path _requested_filename;
  FileEventNotifier _file_event_notifier;
  RedirectableFileHandlerConfig _config;
};

} // namespace quill

#include "quill/handlers/RedirectableFileHandler.h"
#include "quill/detail/misc/FileUtilities.h" // for append_date_to_filename
#include "quill/detail/misc/Common.h"        // for QUILL_UNLIKELY

namespace
{
// Duplicated from the FileHandler, should be centralized if I create a PR to share this...
QUILL_NODISCARD quill::fs::path get_appended_filename(quill::fs::path const& filename,
                                                      quill::FilenameAppend append_to_filename,
                                                      quill::Timezone timezone)
{
  if ((append_to_filename == quill::FilenameAppend::None) || (filename == "/dev/null"))
  {
    return filename;
  }

  if (append_to_filename == quill::FilenameAppend::StartDate)
  {
    return quill::detail::append_date_time_to_filename(filename, false, timezone);
  }

  if (append_to_filename == quill::FilenameAppend::StartDateTime)
  {
    return quill::detail::append_date_time_to_filename(filename, true, timezone);
  }

  return quill::fs::path{};
}
} // namespace

namespace quill
{

/***/
RedirectableFileHandler::RedirectableFileHandler( fs::path const& filename, RedirectableFileHandlerConfig const& config, FileEventNotifier file_event_notifier )
  : FileHandler(filename, static_cast<FileHandlerConfig const&>(config), std::move(file_event_notifier)),
    _config(config)
{
}

/***/
void RedirectableFileHandler::write(fmt_buffer_t const& formatted_log_message, TransitEvent const& log_event)
{
  if (std::lock_guard lock{_mutex}; QUILL_UNLIKELY(!_requested_filename.empty()))
  {
      // EDIT:  I'm currently flushing externally, but should probably flush here like the rotating log file does.
      close_file();

      if(_requested_filename.has_parent_path())
      {
          fs::create_directories(_requested_filename.parent_path());
      }

      _requested_filename = get_appended_filename(_requested_filename, _config.append_to_filename(), _config.timezone()),

      open_file(_requested_filename, "w");
      _requested_filename.clear();
  }

  // write to file
  StreamHandler::write(formatted_log_message, log_event);
}

} // namespace quill

[odygrd]

Your use case sounds ideal for creating multiple Logger objects, one Logger per dataset, I would personally do that.

For example you can have a base class like the below that creates a new logger when a dataset is created. If you want only a single logger then you can access it via the DatasetLoggerManager class

#include "quill/Quill.h"

#include <unordered_map>

class DatasetLoggerManager
{
public:
  void register_logger(uint32_t id, quill::Logger* logger)
  {
    _logger_map[id] = logger;
  }

  void remove_logger(uint32_t id)
  {
    _logger_map.erase(id);
  }

  void set_logger(uint32_t dataset_id)
  {
    if (auto search = _logger_map.find(dataset_id); search != std::end(_logger_map))
    {
      _logger = search->second;
    }
  }

  quill::Logger* get_logger()
  {
    return _logger;
  }

private:
  std::unordered_map<uint32_t, quill::Logger*> _logger_map;
  quill::Logger* _logger{nullptr};
};

class DatasetBase
{
public:
  DatasetBase(DatasetLoggerManager& dlm) : _dlm(dlm)
  {
    std::string const dataset_name = "dataset_" + std::to_string(_id);

    std::shared_ptr<quill::Handler> file_handler =
      quill::file_handler(dataset_name + ".log",
                          []()
                          {
                            quill::FileHandlerConfig cfg;
                            cfg.set_open_mode('w');
                            return cfg;
                          }());

    _logger = quill::create_logger(dataset_name, std::move(file_handler));
    _dlm.register_logger(_id, _logger);
  }

  ~DatasetBase()
  {
    quill::flush();
    quill::remove_logger(_logger);
    _dlm.remove_logger(_id);
  }

  [[nodiscard]] quill::Logger* get_logger() const noexcept
  {
    return _logger;
  }

  [[nodiscard]] uint32_t get_id() const noexcept
  {
    return _id;
  }

private:
  static inline uint32_t _global_id{0};

  DatasetLoggerManager& _dlm;
  quill::Logger* _logger{nullptr};
  uint32_t _id{_global_id++};
};

int main()
{
  // Start the logging backend thread
  quill::start();

  DatasetLoggerManager dlm{};
  DatasetBase d1{dlm};
  DatasetBase d2{dlm};

  dlm.set_logger(d1.get_id());

  LOG_INFO(d1.get_logger(), "log example {}", 1);
  LOG_INFO(dlm.get_logger(), "log example {}", 1);

  dlm.set_logger(d2.get_id());

  LOG_INFO(d2.get_logger(), "log example {}", 2);
  LOG_INFO(dlm.get_logger(), "log example {}", 2);
}

If you still would like to go with the RedirectableFileHandler that solution seems correct and it should work fine.

Some things to consider :

• The write() function is called by the backend logging thread on each log statement. Taking the mutex is probably okay but closing and opening the file is a slow operation and doing that on each log message is not ideal. You probably want to cache the existing filename and only close/open when the filename has changed. I recommend you run the backend logging thread throughput benchmark with your custom Handler if you want to be sure. It really depends how extensively you want to log, if you make the backend logging thread too slow then the spsc queue from the threads that are issuing the logs can become full and that will cause a reallocation (https://github.com/odygrd/quill/blob/master/benchmarks/backend_throughput/quill_backend_throughput.cpp)

• You do not need to externally flush, OS should flush automatically when the file is closed

• The main disadvantage of the RedirectableFileHandler solution is that it always requires to take a mutex lock on the backend worker thread for each log statement, even if you cache the file name and do not reopen it each time. However that can be okay as long as you are not exceeding the backend logging thread throughput

[rexkerr]

Thank you, this gives me some ideas on how to proceed -- I did recognize the cost of the mutex on every log message. I am currently hoping that I will be able to pass the current logger object to the code that will use it, but wanted to be prepared in case I ran into a scenario where that wasn't possible.