Is it possible to redirect logs to new sinks temporarily?

[espakm]

Hello,
I would like to redirect the logs after an event, for a period of a "session" and then continue with the original sinks after the session ends.
How is it possible to do that?

I tried the suggessions in #658, and it seemed that last option (3) would be the best, i.e.

• flush and remove all the current loggers
• recreate the root logger with the new sinks
• (new loggers will be created as needed based on the new root logger)
  and when the session ends, again:
• flush and remove all the current loggers
• recreate the root logger with the old sinks
• (new loggers will be created as needed based on the new/old root logger)

It looks simple, but cannot I get it working stably. I suspect some thread tries to log through a logger that is being removed from another thread. Is there a way to prevent this?

Thanks a lot!

[odygrd]

Hey, after calling remove_logger the user isn’t expected to use it anymore from other threads.

The logger is marked as invalid but still exists. Backend thread waits until every log from this logger is processed and then removes it. Then the logger* is invalid and if you try to access it you will likely crash. That is only checked by an assert in the library

quill/include/quill/Logger.h

Line 96 in 99b7cb3

assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log");

You could check for

quill/include/quill/core/LoggerBase.h

Line 111 in 99b7cb3

QUILL_NODISCARD bool is_valid_logger() const noexcept

but it doesn’t solve the problem as the Logger will be removed the memory Logger* is pointing is now invalid and you will still crash

so you need to sync it on your side

std::atomic<Logger*> logger;

Logger* l = logger.exchange(nullptr)
if (l) { 
  remove_logger(l); 
}

// before logging 
if (auto* l = logger.load(memory_order_acquire); l)
{
LOG_INFO(l,…);
}

But instead of doing the above why don’t you just create a new logger with the redirection sink. When you want to redirect you just simply update the Logger* you pass to LOG_INFO with a new logger without additional checks.

[espakm]

I am not sure that this is thread-safe. I still get crashes.
I am doing something like this:

std::atomic<Logger*> logger;
...
Logger* l = logger.exchange(nullptr)
if (l) { 
  remove_logger(l); 
}
... create a new logger with new sinks and assign it to `l` ...
logger = l;

And at logging:

if (auto* l = logger.load(std::memory_order_acquire); l) {
   LOG_INFO(l,…);
}

This ensures that a valid logger is passed to the LOG_INFO macro, always, but:

1. the logger may get invalidated by the time the code generated by the macro does something with it
2. if the logger is being "reconfigured" (replaced) when the "if" condition is evaluated, then the log message will be lost.

2. could be resolved by using a loop instead of an if, but I do not see a solution for 1).

Is there a thread-safe solution other than wrapping every log statement with mutex locks?

[odygrd]

on x86-64 you can have something like this for example even without atomics.
sleep is just for the example demonstration

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

#include <iostream>
#include <string>
#include <utility>
#include <chrono>

#define ACCESS_ONCE(x) (*(volatile typeof(x)*)&(x))

int main()
{
  quill::BackendOptions backend_options;
  quill::Backend::start(backend_options);

  quill::Logger* logger_1 = quill::Frontend::create_or_get_logger(
    "logger_1", quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1"));

  quill::Logger* logger_2 = quill::Frontend::create_or_get_logger(
    "session_logger", quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1"));

  alignas(8) quill::Logger* logger = logger_1;

  auto t1 = std::thread(
    [&logger]()
    {
      for (int i = 0; i < 20; ++i)
      {
        LOG_INFO(logger, "{}", i);

        // or strictly:
        // LOG_INFO(ACCESS_ONCE(logger), "{}", i);

        std::this_thread::sleep_for(std::chrono::milliseconds {300});
      }
    });

  auto next_session = std::chrono::steady_clock::now() + std::chrono::seconds{1};
  for (size_t session_transition = 0; session_transition < 4; ++session_transition)
  {
    auto now = std::chrono::steady_clock::now();
    while (now < next_session)
    {
      // wait
      std::this_thread::sleep_for(std::chrono::microseconds{100});
      now = std::chrono::steady_clock::now();
    }

    // Session transition
    next_session = now + std::chrono::seconds{1};

    if (logger == logger_1)
    {
      logger = logger_2;
    }
    else
    {
      logger = logger_1;
    }
  }

  t1.join();
}

will also work with globals, e.g

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

#include <iostream>
#include <string>
#include <utility>
#include <chrono>

#define ACCESS_ONCE(x) (*(volatile typeof(x)*)&(x))

quill::Logger* logger_1 = quill::Frontend::create_or_get_logger(
  "logger_1", quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1"));

quill::Logger* logger_2 = quill::Frontend::create_or_get_logger(
  "session_logger", quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1"));

alignas(8) quill::Logger* logger = logger_1;

int main()
{
  quill::BackendOptions backend_options;
  quill::Backend::start(backend_options);

  auto t1 = std::thread(
    []()
    {
      for (int i = 0; i < 20; ++i)
      {
        LOG_INFO(logger, "{}", i);

        // or strictly:
        // LOG_INFO(ACCESS_ONCE(logger), "{}", i);

        std::this_thread::sleep_for(std::chrono::milliseconds {300});
      }
    });

  auto next_session = std::chrono::steady_clock::now() + std::chrono::seconds{1};
  for (size_t session_transition = 0; session_transition < 4; ++session_transition)
  {
    auto now = std::chrono::steady_clock::now();
    while (now < next_session)
    {
      // wait
      std::this_thread::sleep_for(std::chrono::microseconds{100});
      now = std::chrono::steady_clock::now();
    }

    // Session transition
    next_session = now + std::chrono::seconds{1};

    if (logger == logger_1)
    {
      logger = logger_2;
    }
    else
    {
      logger = logger_1;
    }
  }

  t1.join();
}

[espakm]

Hi,
thank you for the quick and detailed answer!
After more debugging, I found that the loggers were not only removed when a new logging session started, but actually, there were two instances of the singleton that is meant to initialise the backend and create the root logger. This was because the singleton was compiled into a static lib that was also linked into a shared lib and the main executable. So, weirdly, I ended up with two instances of the singleton, causing all sorts of troubles.
The solution was changing the library with the singleton a shared lib, and I also had to export Quill's symbols from it with the WINDOWS_EXPORT_ALL_SYMBOLS target property.
There is a nice example in the Quill codebase where I found this hint.
I still get crashes occasionally, I can finally check if the suggestions above work.
Thanks!

[odygrd]

Thanks for the update! Yes, unfortunately, on Windows, sharing a singleton across multiple DLLs can lead to this issue. I've spent a lot of time debugging this in the past as well.

I've added a check to help detect this problem—if it passes CI, I'm happy to merge: #695. Feel free to take a look.

Also, if you're loading DLLs dynamically, you may need this as well: #586.

[espakm]

This was on Mac, I have not tried it on Windows yet.
It seems that the sinks get destroyed before the time the log message would be processed by the background worker thread. The crash happens always somewhere else, last time here:

https://github.com/odygrd/quill/blob/v8.0.0/include/quill/backend/BackendWorker.h#L964

The loop starts, but the sink is null, and in frames further back in the backtrace I see that *transit_event->logger_base has no sinks (empty vector). That is weird, because then how did the backend worker enter that loop at all? So, this makes me think that the logger is destroyed after the log message is sent but before it is processed by the background worker thread. Or eventually, after a reference to a valid logger is retrieved and the log message is sent.

But instead of doing the above why don’t you just create a new logger with the redirection sink. When you want to redirect you just simply update the Logger* you pass to LOG_INFO with a new logger without additional checks.

That is what I'm doing, actually.
What I'm doing now:

• Start the backend
• create a root logger with sinks
• when something needs to be logged to a specific logger:
  • checking if the logger is initialised / still valid:
  • if no, recreate the logger with the current root logger
  • call Quill LOG macro
• when sinks needs to be reconfigured:
  • remove all current loggers
  • remove root logger
  • recreate root logger with the new sinks

[espakm]

I may have found a solution.
Instead of removing every logger and creating a new root logger with the required sinks, it is safer to stop the backend, start it again, and then creating the new root logger.
It's been running for 10min without crash! 😍

[espakm]

This "solution" was wrong, one test passed with the change, but others failed because of it.

[odygrd]

start()is wrapped under call_once so I was not sure how you were doing this without using some internal api

quill/include/quill/Backend.h

Line 38 in 465e85e

std::call_once(detail::BackendManager::instance().get_start_once_flag(),

You do not need to remove the previous logger, just create a new logger with a unique id and exchange the pointers, something like this should work on Mac for example

it is not safe to call remove_logger(old_logger) even after logger.exchange(latest_logger); because old_logger could be loaded and still used while inside the LOG_INFO macro.

Probably you could call remove_logger(old_logger) a few seconds later after the atomic exchange (so that will probably make sure that no thread was inside LOG_INFO with the old_logger), but it is much easier just to ignore the old Loggers and simply not use them anymore.

The only difference it will make not calling remove_logger is in the file example, the underlying file will remain still open since the Logger still exists

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

#include <chrono>
#include <iostream>
#include <string>
#include <utility>

int main()
{
  quill::BackendOptions backend_options;
  quill::Backend::start(backend_options);

  std::atomic<uint32_t> counter{0};

  std::atomic<quill::Logger*> logger = quill::Frontend::create_or_get_logger(
    "logger_" + std::to_string(counter.fetch_add(1)),
    quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1"));

  // Thread 1, 2 - logs using the logger*
  std::vector<std::thread> log_threads;

  for (size_t t = 0; t < 2; ++t)
  {
    log_threads.push_back(std::thread(
      [&logger]()
      {
        for (int i = 0; i < 30; ++i)
        {
          LOG_INFO(logger.load(std::memory_order_acquire), "{}", i);
          std::this_thread::sleep_for(std::chrono::milliseconds{100 + i * 10});
        }
      }));
  }

  // Thread 3, 4 - session switch
  std::vector<std::thread> session_switch_threads;

  for (size_t t = 0; t < 2; ++t)
  {
    session_switch_threads.push_back(std::thread(
      [&logger, &counter, t]()
      {
        auto next_session = std::chrono::steady_clock::now() + std::chrono::seconds{1} +
          std::chrono::milliseconds{t * 100};

        for (size_t session_transition = 0; session_transition < 4; ++session_transition)
        {
          auto now = std::chrono::steady_clock::now();
          while (now < next_session)
          {
            // wait
            std::this_thread::sleep_for(std::chrono::microseconds{50});
            now = std::chrono::steady_clock::now();
          }

          // Session transition
          next_session = now + std::chrono::seconds{1};

          // create a new logger
          quill::Logger* latest_logger = quill::Frontend::create_or_get_logger(
            "logger_" + std::to_string(counter.fetch_add(1)),
            quill::Frontend::create_or_get_sink<quill::ConsoleSink>("sink_id_1"));

          // swap with the active logger
          logger.exchange(latest_logger);
        }
      }));
  }

  for (auto& t : log_threads)
  {
    t.join();
  }

  for (auto& t : session_switch_threads)
  {
    t.join();
  }
}

or with logging to a different file for example

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

#include <chrono>
#include <iostream>
#include <string>
#include <utility>

int main()
{
  quill::BackendOptions backend_options;
  quill::Backend::start(backend_options);

  std::atomic<uint32_t> counter{0};

  std::string const cnt = std::to_string(counter.fetch_add(1));
  std::atomic<quill::Logger*> logger = quill::Frontend::create_or_get_logger(
    "logger_" + cnt,
    quill::Frontend::create_or_get_sink<quill::FileSink>("log_file" + cnt));

  // Thread 1, 2 - logs using the logger*
  std::vector<std::thread> log_threads;

  for (size_t t = 0; t < 2; ++t)
  {
    log_threads.push_back(std::thread(
      [&logger]()
      {
        for (int i = 0; i < 30; ++i)
        {
          LOG_INFO(logger.load(std::memory_order_acquire), "{}", i);
          std::this_thread::sleep_for(std::chrono::milliseconds{100 + i * 10});
        }
      }));
  }

  // Thread 3, 4 - session switch
  std::vector<std::thread> session_switch_threads;

  for (size_t t = 0; t < 2; ++t)
  {
    session_switch_threads.push_back(std::thread(
      [&logger, &counter, t]()
      {
        auto next_session = std::chrono::steady_clock::now() + std::chrono::seconds{1} +
          std::chrono::milliseconds{t * 100};

        for (size_t session_transition = 0; session_transition < 4; ++session_transition)
        {
          auto now = std::chrono::steady_clock::now();
          while (now < next_session)
          {
            // wait
            std::this_thread::sleep_for(std::chrono::microseconds{50});
            now = std::chrono::steady_clock::now();
          }

          // Session transition
          next_session = now + std::chrono::seconds{1};

          // create a new logger to a new file
          std::string const cnt = std::to_string(counter.fetch_add(1));
          std::atomic<quill::Logger*> latest_logger = quill::Frontend::create_or_get_logger(
            "logger_" + cnt,
            quill::Frontend::create_or_get_sink<quill::FileSink>("log_file" + cnt));

          // swap with the active logger
          logger.exchange(latest_logger);
        }
      }));
  }

  for (auto& t : log_threads)
  {
    t.join();
  }

  for (auto& t : session_switch_threads)
  {
    t.join();
  }
}

[odygrd]

another solution would be to create a logger with unique id per thread, that way you can call remove_logger without having to worry that another thread is using it while it is being removed for example

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

#include <chrono>
#include <iostream>
#include <string>
#include <utility>

int main()
{
  quill::BackendOptions backend_options;
  quill::Backend::start(backend_options);

  std::atomic<uint32_t> counter{0};

  std::vector<std::thread> log_threads;

  for (size_t t = 0; t < 2; ++t)
  {
    log_threads.push_back(std::thread(
      [&counter, t]()
      {
        uint32_t logger_id = 0;

        uint32_t counter_cached = counter.load();
        std::string unique_logger_id = std::to_string(t) + "_" + std::to_string(logger_id);

        quill::Logger* logger_for_thread = quill::Frontend::create_or_get_logger(
          "logger_" + unique_logger_id,
          quill::Frontend::create_or_get_sink<quill::FileSink>("log_file" + std::to_string(counter_cached)));

        for (int i = 0; i < 30; ++i)
        {
          LOG_INFO(logger_for_thread, "{}", i);

          uint32_t const count_val = counter.load();
          if (counter_cached != count_val)
          {
            counter_cached = count_val;

            // session switch
            quill::Logger* old_logger = logger_for_thread;

            // create new logger
            logger_id += 1;
            unique_logger_id = std::to_string(t) + "_" + std::to_string(logger_id);
            logger_for_thread = quill::Frontend::create_or_get_logger(
              "logger_" + unique_logger_id,
              quill::Frontend::create_or_get_sink<quill::FileSink>("log_file" + std::to_string(counter_cached)));

            // safe - because no other thread is using that logger (see unique_logger_id)
            quill::Frontend::remove_logger(old_logger);
          }

          std::this_thread::sleep_for(std::chrono::milliseconds{100 + i * 10});
        }
      }));
  }

  auto next_session = std::chrono::steady_clock::now() + std::chrono::seconds{1};

  for (size_t session_transition = 0; session_transition < 4; ++session_transition)
  {
    auto now = std::chrono::steady_clock::now();
    while (now < next_session)
    {
      // wait
      std::this_thread::sleep_for(std::chrono::microseconds{50});
      now = std::chrono::steady_clock::now();
    }

    // Session transition
    next_session = now + std::chrono::seconds{1};
    counter.fetch_add(1);
  }

  for (auto& t : log_threads)
  {
    t.join();
  }
}

[odygrd]

hey, I have made the follow improvements to master :

• Cross platform duplicated backend thread detection for the linker issues
• It is possible now to call quill::Backend::stop() then quill::Backend::start() again for the backend thread
• Added remove_logger_blocking this will block the caller thread until the logger is removed by the backend. https://github.com/odygrd/quill/blob/master/docs/examples/quill_docs_example_loggers_remove.cpp

[espakm]

The backend has started, backend::stop() never called.
There are two threads, one in the Logger, here:

quill/include/quill/Logger.h

Line 300 in ef367b0

std::this_thread::sleep_for(std::chrono::nanoseconds{sleep_duration_ns});

called from here:

quill/include/quill/Logger.h

Line 211 in ef367b0

this->flush_log();

and the other in the backend worker, here:

quill/include/quill/backend/BackendWorker.h

Line 330 in ef367b0

_wake_up_cv.wait_for(lock, _options.sleep_duration, [this] { return _wake_up_flag; });

called from here:

quill/include/quill/backend/BackendWorker.h

Line 177 in ef367b0

QUILL_TRY { _poll(); }

The poll is running, if I continue and pause the execution, it always stops at a different point, but the Logger seems to stay in place, which tells me that the background_flushed atomic never gets set. It is passed to the log_statement() call in line 283, but not sure how, as the macro metadata is supposed to be followed by a format string, not a pointer. I may miss something.

[odygrd]

if you mean this line here

quill/include/quill/Logger.h

Line 283 in ef367b0

LogLevel::None, &macro_metadata, reinterpret_cast<uintptr_t>(backend_thread_flushed_ptr)))

log_statement accepts any argument, the backend knows how to decode it because it sees MacroMetadata::Event::Flush

Do you see other log statements from the thread that is trying to flush_log ? One suspicion is that you have a duplicated instance of ThreadContextManager

quill/include/quill/core/ThreadContextManager.h

Line 226 in ef367b0

static ThreadContextManager instance;

like you had for the Backend. In that case Backend does not see the queue for this thread at all so it doesn't process any messages for that queue including log messages

If that is the case then we can add the same protection flag there as in the Backend, it is possible to happen especially on windows with the dlls

maybe add a std::cout statement here in the ctor and see if it is called twice (it shouldn't)

quill/include/quill/core/ThreadContextManager.h

Line 330 in ef367b0

ThreadContextManager() = default;

An older similar issue where it happened is here

#302

[espakm]

In fact, it hangs when a second thread context manager is created. :-o

[odygrd]

yeah it shouldn't happen, make sure you are defining QUILL_DLL_IMPORT correctly plus -DCMAKE_WINDOWS_EXPORT_ALL_SYMBOLS=TRUE e.g.

quill/examples/shared_library/CMakeLists.txt

Line 14 in 8d7d5ea

target_compile_definitions(quill_example_shared_lib PRIVATE QUILL_DLL_IMPORT)

Might worth it to add the same protection there as in the backend

[espakm]

It seems to work if I set QUILL_DLL_IMPORT as a private compile definition and QUILL_DLL_EXPORT as interface.

target_compile_definitions(quill_example_shared_lib
    PRIVATE QUILL_DLL_IMPORT
    INTERFACE QUILL_DLL_EXPORT
)

Thank you