multiple loggers single sink

[jwinarske]

I need to implement two loggers in the same process. One is on primary thread (no backtrace), the second is on secondary thread with backtrace enabled. The primary thread would drain the secondary backtrace to same sink. What's the recommended pattern for implementing this?

[jwinarske]

Something like this? What about mutex on secondary backtrace?

  // main thread
  auto primary_logger = spdlog::get("primary");
  auto secondary_logger = primary_logger->clone("second");
  secondary_logger->enable_backtrace(128);
  // pass pointer of secondary_logger to other thread

  // do some work on secondary thread
  secondary_logger->info("hello");

  // main thread -> periodically call
  secondary_logger->dump_backtrace();

[tt4g]

Something like this?

Yes.
See also Wiki: https://github.com/gabime/spdlog/wiki/2.-Creating-loggers#creating-loggers-with-multiple-sinks

What about mutex on secondary backtrace?

backtracer is thread-safe.

Enable/Disable backtrace (mutex):

• logger:

  spdlog/include/spdlog/logger-inl.h

  Lines 107 to 117 in 7e635fc

  	// create new backtrace sink and move to it all our child sinks
  	SPDLOG_INLINE void logger::enable_backtrace(size_t n_messages)
  	{
  	tracer_.enable(n_messages);
  	}
  	// restore orig sinks and level and delete the backtrace sink
  	SPDLOG_INLINE void logger::disable_backtrace()
  	{
  	tracer_.disable();
  	}

• backtracer:

  spdlog/include/spdlog/details/backtracer-inl.h

  Lines 33 to 49 in 7e635fc

  	SPDLOG_INLINE void backtracer::enable(size_t size)
  	{
  	std::lock_guard<std::mutex> lock{mutex_};
  	enabled_.store(true, std::memory_order_relaxed);
  	messages_ = circular_q<log_msg_buffer>{size};
  	}
  	SPDLOG_INLINE void backtracer::disable()
  	{
  	std::lock_guard<std::mutex> lock{mutex_};
  	enabled_.store(false, std::memory_order_relaxed);
  	}
  	SPDLOG_INLINE bool backtracer::enabled() const
  	{
  	return enabled_.load(std::memory_order_relaxed);
  	}

Dump backtrace (mutex):

• logger:

  spdlog/include/spdlog/logger-inl.h

  Lines 210 to 219 in 7e635fc

  	SPDLOG_INLINE void logger::dump_backtrace_()
  	{
  	using details::log_msg;
  	if (tracer_.enabled() && !tracer_.empty())
  	{
  	sink_it_(log_msg{name(), level::info, "****************** Backtrace Start ******************"});
  	tracer_.foreach_pop([this](const log_msg &msg) { this->sink_it_(msg); });
  	sink_it_(log_msg{name(), level::info, "****************** Backtrace End ********************"});
  	}
  	}

• backtracer:

  spdlog/include/spdlog/details/backtracer-inl.h

  Lines 63 to 73 in 7e635fc

  	// pop all items in the q and apply the given fun on each of them.
  	SPDLOG_INLINE void backtracer::foreach_pop(std::function<void(const details::log_msg &)> fun)
  	{
  	std::lock_guard<std::mutex> lock{mutex_};
  	while (!messages_.empty())
  	{
  	auto &front_msg = messages_.front();
  	fun(front_msg);
  	messages_.pop_front();
  	}
  	}

[jwinarske]

thanks!

[jwinarske]

hmm. I'm seeing redundant log output even though I'm only writing to secondary logger.

auto console_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
auto logger = std::make_shared<spdlog::logger>("primary", console_sink);
spdlog::set_default_logger(logger);

auto primary_logger = spdlog::get("primary");
m_vm_logger = primary_logger->clone("vm");
m_vm_logger->enable_backtrace(256);

Write Thread

m_vm_logger->info(message);

Drain Thread

m_vm_logger->dump_backtrace();

Log has:

[info] The Dart VM service is listening on http://127.0.0.1:41845/wQIuWqx9KkQ=/
[info] ****************** Backtrace Start ******************
[info] The Dart VM service is listening on http://127.0.0.1:41845/wQIuWqx9KkQ=/
[info] ****************** Backtrace End ********************

I would not expect the leading log entry, only the backtrace dump.

Also is there an option to disable the Backtrace Start/End banner?

[jwinarske]

Creating a logger without using clone also produces double log output. Am I missing something, or is that by design?

[tt4g]

This is design. The backtrace API is the ability to replay log messages for debugging.
It is not designed for the purpose of saving logs and outputting them later.

Create a custom sink to buffer logs using ringbuffer_sink (#2774, #1623).
See: https://github.com/gabime/spdlog/wiki/4.-Sinks#implementing-your-own-sink

#include <mutex>

#include "spdlog/sinks/base_sink.h"
#include "spdlog/sinks/ringbuffer_sink.h"
#include "spdlog/details/null_mutex.h"

template<typename Mutex>
class buffer_sink : public spdlog::sinks::base_sink <Mutex>
{

...
protected:
    void sink_it_(const spdlog::details::log_msg& msg) override
    {
		this->ringbuffer.log(msg);
    }

    void flush_() override 
    {
        // Impl
    }

private:
	spdlog::sinks::ringbuffer_sink_st ringbuffer;
};

using buffer_sink_mt = buffer_sink<std::mutex>;
using buffer_sink_st = buffer_sink<spdlog::details::null_mutex>;

[gabime]

If you don't want to see duplicates just set the secondary logger level to off.

[jwinarske]

which is why I was liking the backtrace implementation. Only issue is I need to fork it to remove the banners.

[tt4g]

Only issue is I need to fork it to remove the banners.

This can be solved by ringbuffer_sink (#1623), so the PR is closed (#2778).

[jwinarske]

I tried out ringbuffer_sink. After some fiddling I moved to the below pattern. Simple and works great.

definition

auto m_vm_queue = std::make_shared<std::queue<std::string>>();

writer thread

std::scoped_lock<std::mutex> lock(ctx->m_queue_lock);
ctx->m_vm_queue->push(message);

logging thread

  if (!m_vm_queue->empty()) {
    std::scoped_lock<std::mutex> lock(m_queue_lock);
    for (int i = 0; i < kVmLogChunkMax; i++) {
      spdlog::info(m_vm_queue->front());
      m_vm_queue->pop();
      if (m_vm_queue->empty())
        break;
    }
  }

[gabime]

std::scoped_lockstd::mutex lock(ctx->m_queue_lock);
ctx->m_vm_queue->push(message);

Lots of allocations with this way..
The ring buffer allocates much less I believe (e.g. if the log message < 250 bytes, it reuses existing pre allocated memory). All that is left is to add some way to iterate it instead of creating a vector(e.g

spdlog/include/spdlog/details/backtracer-inl.h

Line 64 in 76dfc7e

SPDLOG_INLINE void backtracer::foreach_pop(std::function<void(const details::log_msg &)> fun)

)

[jwinarske]

Are you suggesting to use ringbuffer sink and backtracer?

What's the pattern to remove items from ringbuffer sink?

[gabime]

Either use the backtracer, or use the ringbuffer and add a foreach_pop impl (see above) , or maybe even better, iterator support(pr is welcome).

That being said, if the rate of your logs is not high, maybe your solution is good enough.

[jwinarske]

I'll take a look at your suggestion. Thanks.