diff --git a/README.md b/README.md index 4fcef570..6ff4be59 100644 --- a/README.md +++ b/README.md @@ -37,6 +37,7 @@ Very fast, header-only/compiled, C++ logging library. [![Build Status](https://t * Very fast (see [benchmarks](#benchmarks) below). * Headers only, just copy and use. Or use as a compiled library. * Feature rich formatting, using the excellent [fmt](https://github.com/fmtlib/fmt) library. +* [Backtrace](#backtrace-support) support - store debugging messages in a ring buffer for later inspection. * Fast asynchronous mode (optional) * [Custom](https://github.com/gabime/spdlog/wiki/3.-Custom-formatting) formatting. * Multi/Single threaded loggers. @@ -137,15 +138,17 @@ void daily_example() ``` --- -#### Cloning loggers +#### Backtrace support ```c++ -// clone a logger and give it new name. -// Useful for creating subsystem loggers from some "root" logger -void clone_example() +// Loggers can store in a ring buffer all messages (including debug/trace) for later inspection. +// When needed, call dump_backtrace() to see what happened: +spdlog::enable_backtrace(32); // create ring buffer with capacity of 32 messages +for(int i = 0; i < 100; i++) { - auto network_logger = spdlog::get("root")->clone("network"); - network_logger->info("Logging network stuff.."); + spdlog::debug("Backtrace message {}", i); // not logged yet.. } +// e.g. if some error happened: +spdlog::dump_backtrace(); // log them now! ``` --- diff --git a/bench/async_bench.cpp b/bench/async_bench.cpp index e5732725..fc49cdd8 100644 --- a/bench/async_bench.cpp +++ b/bench/async_bench.cpp @@ -48,6 +48,7 @@ int count_lines(const char *filename) void verify_file(const char *filename, int expected_count) { + spdlog::info("Verifying {} to contain {:n} line..", filename, expected_count); auto count = count_lines(filename); if (count != expected_count) { @@ -115,9 +116,7 @@ int main(int argc, char *argv[]) auto file_sink = std::make_shared(filename, true); auto logger = std::make_shared("async_logger", std::move(file_sink), std::move(tp), async_overflow_policy::block); bench_mt(howmany, std::move(logger), threads); -#ifdef SPDLOG_ASYNC_BENCH_VERIFY - verify_file(filename, howmany); -#endif // SPDLOG_ASYNC_BENCH_VERIFY + // verify_file(filename, howmany); } spdlog::info(""); @@ -125,6 +124,7 @@ int main(int argc, char *argv[]) spdlog::info("Queue Overflow Policy: overrun"); spdlog::info("*********************************"); // do same test but discard oldest if queue is full instead of blocking + filename = "logs/basic_async-overrun.log"; for (int i = 0; i < iters; i++) { auto tp = std::make_shared(queue_size, 1); @@ -141,7 +141,6 @@ int main(int argc, char *argv[]) perror("Last error"); return 1; } - return 0; } diff --git a/bench/latency.cpp b/bench/latency.cpp index 2a7787d6..730226ca 100644 --- a/bench/latency.cpp +++ b/bench/latency.cpp @@ -90,29 +90,50 @@ int main(int argc, char *argv[]) disabled_logger->set_level(spdlog::level::off); benchmark::RegisterBenchmark("disabled-at-compile-time", bench_disabled_macro, disabled_logger); benchmark::RegisterBenchmark("disabled-at-runtime", bench_logger, disabled_logger); + // with backtrace of 64 + auto tracing_disabled_logger = std::make_shared("bench", std::make_shared()); + tracing_disabled_logger->enable_backtrace(64); + benchmark::RegisterBenchmark("disabled-at-runtime/backtrace", bench_logger, tracing_disabled_logger); auto null_logger_st = std::make_shared("bench", std::make_shared()); benchmark::RegisterBenchmark("null_sink_st (500_bytes c_str)", bench_c_string, std::move(null_logger_st)); benchmark::RegisterBenchmark("null_sink_st", bench_logger, null_logger_st); + // with backtrace of 64 + auto tracing_null_logger_st = std::make_shared("bench", std::make_shared()); + tracing_null_logger_st->enable_backtrace(64); + benchmark::RegisterBenchmark("null_sink_st/backtrace", bench_logger, tracing_null_logger_st); // basic_st auto basic_st = spdlog::basic_logger_st("basic_st", "latency_logs/basic_st.log", true); benchmark::RegisterBenchmark("basic_st", bench_logger, std::move(basic_st))->UseRealTime(); spdlog::drop("basic_st"); + // with backtrace of 64 + auto tracing_basic_st = spdlog::basic_logger_st("tracing_basic_st", "latency_logs/tracing_basic_st.log", true); + tracing_basic_st->enable_backtrace(64); + benchmark::RegisterBenchmark("basic_st/backtrace", bench_logger, std::move(tracing_basic_st))->UseRealTime(); + spdlog::drop("tracing_basic_st"); // rotating st auto rotating_st = spdlog::rotating_logger_st("rotating_st", "latency_logs/rotating_st.log", file_size, rotating_files); benchmark::RegisterBenchmark("rotating_st", bench_logger, std::move(rotating_st))->UseRealTime(); spdlog::drop("rotating_st"); + // with backtrace of 64 + auto tracing_rotating_st = + spdlog::rotating_logger_st("tracing_rotating_st", "latency_logs/tracing_rotating_st.log", file_size, rotating_files); + benchmark::RegisterBenchmark("rotating_st/backtrace", bench_logger, std::move(tracing_rotating_st))->UseRealTime(); + spdlog::drop("tracing_rotating_st"); // daily st auto daily_st = spdlog::daily_logger_mt("daily_st", "latency_logs/daily_st.log"); benchmark::RegisterBenchmark("daily_st", bench_logger, std::move(daily_st))->UseRealTime(); spdlog::drop("daily_st"); + auto tracing_daily_st = spdlog::daily_logger_mt("tracing_daily_st", "latency_logs/daily_st.log"); + benchmark::RegisterBenchmark("daily_st/backtrace", bench_logger, std::move(tracing_daily_st))->UseRealTime(); + spdlog::drop("tracing_daily_st"); - // // - // // Multi threaded bench, 10 loggers using same logger concurrently - // // + // + // Multi threaded bench, 10 loggers using same logger concurrently + // auto null_logger_mt = std::make_shared("bench", std::make_shared()); benchmark::RegisterBenchmark("null_sink_mt", bench_logger, null_logger_mt)->Threads(n_threads)->UseRealTime(); @@ -138,6 +159,11 @@ int main(int argc, char *argv[]) "async_logger", std::make_shared(), std::move(tp), spdlog::async_overflow_policy::overrun_oldest); benchmark::RegisterBenchmark("async_logger", bench_logger, async_logger)->Threads(n_threads)->UseRealTime(); + auto async_logger_tracing = std::make_shared( + "async_logger_tracing", std::make_shared(), std::move(tp), spdlog::async_overflow_policy::overrun_oldest); + async_logger_tracing->enable_backtrace(32); + benchmark::RegisterBenchmark("async_logger/tracing", bench_logger, async_logger_tracing)->Threads(n_threads)->UseRealTime(); + benchmark::Initialize(&argc, argv); benchmark::RunSpecifiedBenchmarks(); } diff --git a/example/example.cpp b/example/example.cpp index ce57fc9d..2a18677a 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -17,7 +17,6 @@ void multi_sink_example(); void user_defined_example(); void err_handler_example(); void syslog_example(); -void clone_example(); #include "spdlog/spdlog.h" @@ -40,6 +39,18 @@ int main(int, char *[]) spdlog::set_pattern("[%H:%M:%S %z] [%^%L%$] [thread %t] %v"); spdlog::info("This an info message with custom format"); spdlog::set_pattern("%+"); // back to default format + spdlog::set_level(spdlog::level::info); + + // Backtrace support + // Loggers can store in a ring buffer all messages (including debug/trace) for later inspection. + // When needed, call dump_backtrace() to see what happened: + spdlog::enable_backtrace(10); // create ring buffer with capacity of 10 messages + for (int i = 0; i < 100; i++) + { + spdlog::debug("Backtrace message {}", i); // not logged.. + } + // e.g. if some error happened: + spdlog::dump_backtrace(); // log them now! try { @@ -47,7 +58,6 @@ int main(int, char *[]) basic_example(); rotating_example(); daily_example(); - clone_example(); async_example(); binary_example(); multi_sink_example(); @@ -106,14 +116,6 @@ void daily_example() auto daily_logger = spdlog::daily_logger_mt("daily_logger", "logs/daily.txt", 2, 30); } -// Clone a logger and give it new name. -// Useful for creating component/subsystem loggers from some "root" logger. -void clone_example() -{ - auto network_logger = spdlog::default_logger()->clone("network"); - network_logger->info("Logging network stuff.."); -} - #include "spdlog/async.h" void async_example() { diff --git a/include/spdlog/async_logger-inl.h b/include/spdlog/async_logger-inl.h index 45c6d8a9..93dbab7c 100644 --- a/include/spdlog/async_logger-inl.h +++ b/include/spdlog/async_logger-inl.h @@ -10,7 +10,6 @@ #include "spdlog/sinks/sink.h" #include "spdlog/details/thread_pool.h" -#include #include #include @@ -25,7 +24,7 @@ SPDLOG_INLINE spdlog::async_logger::async_logger( {} // send the log message to the thread pool -SPDLOG_INLINE void spdlog::async_logger::sink_it_(details::log_msg &msg) +SPDLOG_INLINE void spdlog::async_logger::sink_it_(const details::log_msg &msg) { if (auto pool_ptr = thread_pool_.lock()) { @@ -53,38 +52,34 @@ SPDLOG_INLINE void spdlog::async_logger::flush_() // // backend functions - called from the thread pool to do the actual job // -SPDLOG_INLINE void spdlog::async_logger::backend_log_(const details::log_msg &incoming_log_msg) +SPDLOG_INLINE void spdlog::async_logger::backend_sink_it_(const details::log_msg &msg) { - SPDLOG_TRY + for (auto &sink : sinks_) { - for (auto &s : sinks_) + if (sink->should_log(msg.level)) { - if (s->should_log(incoming_log_msg.level)) + SPDLOG_TRY { - s->log(incoming_log_msg); + sink->log(msg); } + SPDLOG_LOGGER_CATCH() } } - SPDLOG_LOGGER_CATCH() - if (should_flush_(incoming_log_msg)) + if (should_flush_(msg)) { backend_flush_(); } } -SPDLOG_INLINE void spdlog::async_logger::backend_flush_(){SPDLOG_TRY{for (auto &sink : sinks_){sink->flush(); -} -} -SPDLOG_LOGGER_CATCH() -} - -SPDLOG_INLINE std::shared_ptr spdlog::async_logger::clone(std::string new_name) +SPDLOG_INLINE void spdlog::async_logger::backend_flush_() { - auto cloned = std::make_shared(std::move(new_name), sinks_.begin(), sinks_.end(), thread_pool_, overflow_policy_); - - cloned->set_level(this->level()); - cloned->flush_on(this->flush_level()); - cloned->set_error_handler(this->custom_err_handler_); - return cloned; + for (auto &sink : sinks_) + { + SPDLOG_TRY + { + sink->flush(); + } + SPDLOG_LOGGER_CATCH() + } } diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index 9899837b..f98ba715 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -49,13 +49,10 @@ public: async_logger(std::string logger_name, sink_ptr single_sink, std::weak_ptr tp, async_overflow_policy overflow_policy = async_overflow_policy::block); - std::shared_ptr clone(std::string new_name) override; - protected: - void sink_it_(details::log_msg &msg) override; + void sink_it_(const details::log_msg &msg) override; void flush_() override; - - void backend_log_(const details::log_msg &incoming_log_msg); + void backend_sink_it_(const details::log_msg &incoming_log_msg); void backend_flush_(); private: diff --git a/include/spdlog/details/backtracer.h b/include/spdlog/details/backtracer.h new file mode 100644 index 00000000..9b265a7d --- /dev/null +++ b/include/spdlog/details/backtracer.h @@ -0,0 +1,58 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#include "spdlog/common.h" +#include "spdlog/details/log_msg_buffer.h" +#include "spdlog/details/circular_q.h" +#include "spdlog/sinks/sink.h" +#include + +// Store log messages in circular buffer. +// Useful for storing debug data in case of error/warning happens. + +namespace spdlog { +namespace details { +class backtracer +{ + std::mutex mutex_; + size_t n_messages_; + circular_q messages_; + +public: + explicit backtracer(size_t n_messages) + : n_messages_{n_messages} + , messages_{n_messages} + {} + + backtracer(const backtracer &other) + : n_messages_{other.n_messages_} + , messages_{other.messages_} + {} + + size_t n_messages() const + { + return n_messages_; + } + + void add(const log_msg &msg) + { + std::lock_guard lock{mutex_}; + messages_.push_back(log_msg_buffer{msg}); + } + + // pop all items in the q and apply the give fun on each of them. + void foreach_pop(std::function fun) + { + std::lock_guard lock{mutex_}; + while (!messages_.empty()) + { + log_msg_buffer popped; + messages_.pop_front(popped); + fun(popped); + } + } +}; +} // namespace details +} // namespace spdlog \ No newline at end of file diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index f2976df8..ccd41ecb 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -10,11 +10,12 @@ namespace spdlog { namespace details { struct log_msg { + log_msg() = default; log_msg(source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg); log_msg(string_view_t logger_name, level::level_enum lvl, string_view_t msg); log_msg(const log_msg &other) = default; - const string_view_t logger_name; + string_view_t logger_name; level::level_enum level{level::off}; log_clock::time_point time; size_t thread_id{0}; @@ -24,7 +25,7 @@ struct log_msg mutable size_t color_range_end{0}; source_loc source; - const string_view_t payload; + string_view_t payload; }; } // namespace details } // namespace spdlog diff --git a/include/spdlog/details/log_msg_buffer.h b/include/spdlog/details/log_msg_buffer.h new file mode 100644 index 00000000..3015d26a --- /dev/null +++ b/include/spdlog/details/log_msg_buffer.h @@ -0,0 +1,60 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#include "spdlog/details/log_msg.h" +#include "spdlog/fmt/bundled/core.h" + +namespace spdlog { +namespace details { + +// extend log_msg with internal buffer to store its payload. +// this is needed since log_msg holds string_views that points to stack data. + +class log_msg_buffer : public log_msg +{ + fmt::basic_memory_buffer buffer; + void update_string_views() + { + logger_name = string_view_t{buffer.data(), logger_name.size()}; + payload = string_view_t{logger_name.end(), payload.size()}; + } + +public: + log_msg_buffer() = default; + + explicit log_msg_buffer(const log_msg &orig_msg) + : log_msg{orig_msg} + { + buffer.append(logger_name.begin(), logger_name.end()); + buffer.append(payload.begin(), payload.end()); + update_string_views(); + } + + log_msg_buffer(const log_msg_buffer &other) + : log_msg{other} + { + buffer.append(logger_name.begin(), logger_name.end()); + buffer.append(payload.begin(), payload.end()); + update_string_views(); + } + + log_msg_buffer(log_msg_buffer &&other) + : log_msg{std::move(other)} + , buffer{std::move(other.buffer)} + { + update_string_views(); + } + + log_msg_buffer &operator=(log_msg_buffer &&other) + { + log_msg::operator=(std::move(other)); + buffer = std::move(other.buffer); + update_string_views(); + return *this; + } +}; + +} // namespace details +} // namespace spdlog \ No newline at end of file diff --git a/include/spdlog/details/registry-inl.h b/include/spdlog/details/registry-inl.h index d19e1f15..075a0c7e 100644 --- a/include/spdlog/details/registry-inl.h +++ b/include/spdlog/details/registry-inl.h @@ -67,6 +67,11 @@ SPDLOG_INLINE void registry::initialize_logger(std::shared_ptr new_logge new_logger->set_level(level_); new_logger->flush_on(flush_level_); + if (backtrace_n_messages_ > 0) + { + new_logger->enable_backtrace(backtrace_n_messages_); + } + if (automatic_registration_) { register_logger_(std::move(new_logger)); @@ -135,6 +140,27 @@ SPDLOG_INLINE void registry::set_formatter(std::unique_ptr formatter) } } +SPDLOG_INLINE void registry::enable_backtrace(size_t n_messages) +{ + std::lock_guard lock(logger_map_mutex_); + backtrace_n_messages_ = n_messages; + + for (auto &l : loggers_) + { + l.second->enable_backtrace(n_messages); + } +} + +SPDLOG_INLINE void registry::disable_backtrace() +{ + std::lock_guard lock(logger_map_mutex_); + backtrace_n_messages_ = 0; + for (auto &l : loggers_) + { + l.second->disable_backtrace(); + } +} + SPDLOG_INLINE void registry::set_level(level::level_enum log_level) { std::lock_guard lock(logger_map_mutex_); diff --git a/include/spdlog/details/registry.h b/include/spdlog/details/registry.h index f96a7698..35a117d9 100644 --- a/include/spdlog/details/registry.h +++ b/include/spdlog/details/registry.h @@ -52,6 +52,10 @@ public: // Set global formatter. Each sink in each logger will get a clone of this object void set_formatter(std::unique_ptr formatter); + void enable_backtrace(size_t n_messages); + + void disable_backtrace(); + void set_level(level::level_enum log_level); void flush_on(level::level_enum log_level); @@ -94,6 +98,7 @@ private: std::unique_ptr periodic_flusher_; std::shared_ptr default_logger_; bool automatic_registration_ = true; + size_t backtrace_n_messages_ = 0; }; } // namespace details diff --git a/include/spdlog/details/thread_pool-inl.h b/include/spdlog/details/thread_pool-inl.h index eecfa45c..77d0b1fb 100644 --- a/include/spdlog/details/thread_pool-inl.h +++ b/include/spdlog/details/thread_pool-inl.h @@ -51,7 +51,7 @@ SPDLOG_INLINE thread_pool::~thread_pool() SPDLOG_CATCH_ALL() {} } -void SPDLOG_INLINE thread_pool::post_log(async_logger_ptr &&worker_ptr, details::log_msg &msg, async_overflow_policy overflow_policy) +void SPDLOG_INLINE thread_pool::post_log(async_logger_ptr &&worker_ptr, const details::log_msg &msg, async_overflow_policy overflow_policy) { async_msg async_m(std::move(worker_ptr), async_msg_type::log, msg); post_async_msg_(std::move(async_m), overflow_policy); @@ -100,8 +100,7 @@ bool SPDLOG_INLINE thread_pool::process_next_msg_() { case async_msg_type::log: { - auto msg = incoming_async_msg.to_log_msg(); - incoming_async_msg.worker_ptr->backend_log_(msg); + incoming_async_msg.worker_ptr->backend_sink_it_(incoming_async_msg); return true; } case async_msg_type::flush: @@ -114,8 +113,13 @@ bool SPDLOG_INLINE thread_pool::process_next_msg_() { return false; } + + default: + { + assert(false && "Unexpected async_msg_type"); } - assert(false && "Unexpected async_msg_type"); + } + return true; } diff --git a/include/spdlog/details/thread_pool.h b/include/spdlog/details/thread_pool.h index ff022082..81bd12de 100644 --- a/include/spdlog/details/thread_pool.h +++ b/include/spdlog/details/thread_pool.h @@ -3,7 +3,7 @@ #pragma once -#include "spdlog/details/log_msg.h" +#include "spdlog/details/log_msg_buffer.h" #include "spdlog/details/mpmc_blocking_q.h" #include "spdlog/details/os.h" @@ -27,17 +27,12 @@ enum class async_msg_type terminate }; +#include "spdlog/details/log_msg_buffer.h" // Async msg to move to/from the queue // Movable only. should never be copied -struct async_msg +struct async_msg : log_msg_buffer { - async_msg_type msg_type {async_msg_type::log}; - level::level_enum level {level::info}; - log_clock::time_point time; - size_t thread_id {0}; - fmt::basic_memory_buffer raw; - - source_loc source; + async_msg_type msg_type{async_msg_type::log}; async_logger_ptr worker_ptr; async_msg() = default; @@ -49,25 +44,15 @@ struct async_msg // support for vs2013 move #if defined(_MSC_VER) && _MSC_VER <= 1800 async_msg(async_msg &&other) - : msg_type(other.msg_type) - , level(other.level) - , time(other.time) - , thread_id(other.thread_id) - , raw(move(other.raw)) - , msg_id(other.msg_id) - , source(other.source) + : log_msg_buffer(std::move(other)) + , msg_type(other.msg_type) , worker_ptr(std::move(other.worker_ptr)) {} async_msg &operator=(async_msg &&other) { + *static_cast(this) = std::move(other); msg_type = other.msg_type; - level = other.level; - time = other.time; - thread_id = other.thread_id; - raw = std::move(other.raw); - msg_id = other.msg_id; - source = other.source; worker_ptr = std::move(other.worker_ptr); return *this; } @@ -77,41 +62,21 @@ struct async_msg #endif // construct from log_msg with given type - async_msg(async_logger_ptr &&worker, async_msg_type the_type, details::log_msg &m) - : msg_type(the_type) - , level(m.level) - , time(m.time) - , thread_id(m.thread_id) - , source(m.source) - , worker_ptr(std::move(worker)) - { - raw.append(m.payload.data(), m.payload.data() + m.payload.size()); - } + async_msg(async_logger_ptr &&worker, async_msg_type the_type, const details::log_msg &m) + : log_msg_buffer{m} + , msg_type{the_type} + , worker_ptr{std::move(worker)} + {} async_msg(async_logger_ptr &&worker, async_msg_type the_type) - : msg_type(the_type) - , level(level::off) - , time() - , thread_id(0) - , source() - , worker_ptr(std::move(worker)) + : log_msg_buffer{} + , msg_type{the_type} + , worker_ptr{std::move(worker)} {} explicit async_msg(async_msg_type the_type) - : async_msg(nullptr, the_type) + : async_msg{nullptr, the_type} {} - - // copy into log_msg - log_msg to_log_msg() - { - log_msg msg(string_view_t(worker_ptr->name()), level, string_view_t(raw.data(), raw.size())); - msg.time = time; - msg.thread_id = thread_id; - msg.source = source; - msg.color_range_start = 0; - msg.color_range_end = 0; - return msg; - } }; class thread_pool @@ -129,7 +94,7 @@ public: thread_pool(const thread_pool &) = delete; thread_pool &operator=(thread_pool &&) = delete; - void post_log(async_logger_ptr &&worker_ptr, details::log_msg &msg, async_overflow_policy overflow_policy); + void post_log(async_logger_ptr &&worker_ptr, const details::log_msg &msg, async_overflow_policy overflow_policy); void post_flush(async_logger_ptr &&worker_ptr, async_overflow_policy overflow_policy); size_t overrun_counter(); @@ -152,4 +117,4 @@ private: #ifdef SPDLOG_HEADER_ONLY #include "thread_pool-inl.h" -#endif \ No newline at end of file +#endif diff --git a/include/spdlog/logger-inl.h b/include/spdlog/logger-inl.h index 52d3fd5f..f6f05343 100644 --- a/include/spdlog/logger-inl.h +++ b/include/spdlog/logger-inl.h @@ -8,6 +8,7 @@ #endif #include "spdlog/sinks/sink.h" +#include "spdlog/details/backtracer.h" #include "spdlog/details/pattern_formatter.h" #include @@ -21,13 +22,20 @@ SPDLOG_INLINE logger::logger(const logger &other) , level_(other.level_.load(std::memory_order_relaxed)) , flush_level_(other.flush_level_.load(std::memory_order_relaxed)) , custom_err_handler_(other.custom_err_handler_) -{} +{ + if (other.tracer_) + { + tracer_ = std::make_shared(*other.tracer_); + } +} SPDLOG_INLINE logger::logger(logger &&other) SPDLOG_NOEXCEPT : name_(std::move(other.name_)), sinks_(std::move(other.sinks_)), level_(other.level_.load(std::memory_order_relaxed)), flush_level_(other.flush_level_.load(std::memory_order_relaxed)), - custom_err_handler_(std::move(other.custom_err_handler_)) + custom_err_handler_(std::move(other.custom_err_handler_)), + tracer_(std::move(other.tracer_)) + {} SPDLOG_INLINE logger &logger::operator=(logger other) SPDLOG_NOEXCEPT @@ -52,6 +60,7 @@ SPDLOG_INLINE void logger::swap(spdlog::logger &other) SPDLOG_NOEXCEPT other.flush_level_.store(tmp); custom_err_handler_.swap(other.custom_err_handler_); + tracer_.swap(other.tracer_); } SPDLOG_INLINE void swap(logger &a, logger &b) @@ -59,22 +68,6 @@ SPDLOG_INLINE void swap(logger &a, logger &b) a.swap(b); } -SPDLOG_INLINE void logger::log(source_loc loc, level::level_enum lvl, string_view_t msg) -{ - if (!should_log(lvl)) - { - return; - } - - details::log_msg log_msg(loc, string_view_t(name_), lvl, msg); - sink_it_(log_msg); -} - -SPDLOG_INLINE void logger::log(level::level_enum lvl, string_view_t msg) -{ - log(source_loc{}, lvl, msg); -} - SPDLOG_INLINE bool logger::should_log(level::level_enum msg_level) const { return msg_level >= level_.load(std::memory_order_relaxed); @@ -119,6 +112,23 @@ SPDLOG_INLINE void logger::set_pattern(std::string pattern, pattern_time_type ti set_formatter(std::move(new_formatter)); } +// create new backtrace sink and move to it all our child sinks +SPDLOG_INLINE void logger::enable_backtrace(size_t n_messages) +{ + tracer_ = std::make_shared(n_messages); +} + +// restore orig sinks and level and delete the backtrace sink +SPDLOG_INLINE void logger::disable_backtrace() +{ + tracer_.reset(); +} + +SPDLOG_INLINE void logger::dump_backtrace() +{ + dump_backtrace_(); +} + // flush functions SPDLOG_INLINE void logger::flush() { @@ -152,16 +162,8 @@ SPDLOG_INLINE void logger::set_error_handler(err_handler handler) custom_err_handler_ = handler; } -// create new logger with same sinks and configuration. -SPDLOG_INLINE std::shared_ptr logger::clone(std::string logger_name) -{ - auto cloned = std::make_shared(*this); - cloned->name_ = std::move(logger_name); - return cloned; -} - // protected methods -SPDLOG_INLINE void logger::sink_it_(details::log_msg &msg) +SPDLOG_INLINE void logger::sink_it_(const details::log_msg &msg) { for (auto &sink : sinks_) { @@ -193,6 +195,22 @@ SPDLOG_INLINE void logger::flush_() } } +SPDLOG_INLINE void logger::backtrace_add_(const details::log_msg &msg) +{ + tracer_->add(msg); +} + +SPDLOG_INLINE void logger::dump_backtrace_() +{ + using details::log_msg; + if (tracer_) + { + sink_it_(log_msg{name(), level::info, "****************** Backtrace Start ******************"}); + tracer_->foreach_pop([this](const details::log_msg &msg) { this->sink_it_(msg); }); + sink_it_(log_msg{name(), level::info, "****************** Backtrace End ********************"}); + } +} + SPDLOG_INLINE bool logger::should_flush_(const details::log_msg &msg) { auto flush_level = flush_level_.load(std::memory_order_relaxed); diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index 2778fef4..8151603e 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -38,6 +38,11 @@ #endif namespace spdlog { + +namespace details { +class backtracer; +} + class logger { public: @@ -73,36 +78,36 @@ public: void swap(spdlog::logger &other) SPDLOG_NOEXCEPT; template - void force_log(source_loc loc, level::level_enum lvl, string_view_t fmt, const Args &... args) + void log(source_loc loc, level::level_enum lvl, string_view_t fmt, const Args &... args) { + auto level_enabled = should_log(lvl); + if (!level_enabled && !tracer_) + { + return; + } SPDLOG_TRY { fmt::memory_buffer buf; fmt::format_to(buf, fmt, args...); details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); - sink_it_(log_msg); + if (level_enabled) + { + sink_it_(log_msg); + } + if (tracer_) + { + backtrace_add_(log_msg); + } } SPDLOG_LOGGER_CATCH() } - template - void log(source_loc loc, level::level_enum lvl, string_view_t fmt, const Args &... args) - { - if (should_log(lvl)) - { - force_log(loc, lvl, fmt, args...); - } - } - template void log(level::level_enum lvl, string_view_t fmt, const Args &... args) { log(source_loc{}, lvl, fmt, args...); } - void log(source_loc loc, level::level_enum lvl, const string_view_t msg); - void log(level::level_enum lvl, string_view_t msg); - template void trace(string_view_t fmt, const Args &... args) { @@ -149,13 +154,29 @@ public: template::value, T>::type * = nullptr> void log(source_loc loc, level::level_enum lvl, const T &msg) { - if (!should_log(lvl)) + auto level_enabled = should_log(lvl); + if (!level_enabled && !tracer_) { return; } + SPDLOG_TRY + { + details::log_msg log_msg(loc, name_, lvl, msg); + if (level_enabled) + { + sink_it_(log_msg); + } + if (tracer_) + { + backtrace_add_(log_msg); + } + } + SPDLOG_LOGGER_CATCH() + } - details::log_msg log_msg(loc, name_, lvl, msg); - sink_it_(log_msg); + void log(level::level_enum lvl, string_view_t msg) + { + log(source_loc{}, lvl, msg); } // T cannot be statically converted to string_view or wstring_view @@ -164,18 +185,7 @@ public: T>::type * = nullptr> void log(source_loc loc, level::level_enum lvl, const T &msg) { - if (!should_log(lvl)) - { - return; - } - SPDLOG_TRY - { - fmt::memory_buffer buf; - fmt::format_to(buf, "{}", msg); - details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); - sink_it_(log_msg); - } - SPDLOG_LOGGER_CATCH() + log(loc, lvl, "{}", msg); } template @@ -218,10 +228,16 @@ public: #ifndef _WIN32 #error SPDLOG_WCHAR_TO_UTF8_SUPPORT only supported on windows #else + template - void force_log(source_loc loc, level::level_enum lvl, wstring_view_t fmt, const Args &... args) + void log(source_loc loc, level::level_enum lvl, wstring_view_t fmt, const Args &... args) { - try + auto level_enabled = should_log(lvl); + if (!level_enabled && !tracer_) + { + return; + } + SPDLOG_TRY { // format to wmemory_buffer and convert to utf8 fmt::wmemory_buffer wbuf; @@ -229,22 +245,20 @@ public: fmt::memory_buffer buf; details::os::wstr_to_utf8buf(wstring_view_t(wbuf.data(), wbuf.size()), buf); - details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); - sink_it_(log_msg); + + if (level_enabled) + { + sink_it_(log_msg); + } + if (tracer_) + { + backtrace_add_(log_msg); + } } SPDLOG_LOGGER_CATCH() } - template - void log(source_loc loc, level::level_enum lvl, wstring_view_t fmt, const Args &... args) - { - if (should_log(lvl)) - { - force_log(loc, lvl, fmt, args...); - } - } - template void log(level::level_enum lvl, wstring_view_t fmt, const Args &... args) { @@ -323,6 +337,12 @@ public: void set_pattern(std::string pattern, pattern_time_type time_type = pattern_time_type::local); + // backtrace support. + // efficiently store all debug/trace messages in a circular buffer until needed for debugging. + void enable_backtrace(size_t n_messages); + void disable_backtrace(); + void dump_backtrace(); + // flush functions void flush(); void flush_on(level::level_enum log_level); @@ -336,18 +356,19 @@ public: // error handler void set_error_handler(err_handler); - // create new logger with same sinks and configuration. - virtual std::shared_ptr clone(std::string logger_name); - protected: std::string name_; std::vector sinks_; spdlog::level_t level_{level::info}; spdlog::level_t flush_level_{level::off}; err_handler custom_err_handler_{nullptr}; + std::shared_ptr tracer_; - virtual void sink_it_(details::log_msg &msg); + virtual void sink_it_(const details::log_msg &msg); virtual void flush_(); + + void backtrace_add_(const details::log_msg &msg); + void dump_backtrace_(); bool should_flush_(const details::log_msg &msg); // handle errors during logging. diff --git a/include/spdlog/sinks/daily_file_sink.h b/include/spdlog/sinks/daily_file_sink.h index 32cf6756..341b5c42 100644 --- a/include/spdlog/sinks/daily_file_sink.h +++ b/include/spdlog/sinks/daily_file_sink.h @@ -11,7 +11,6 @@ #include "spdlog/details/os.h" #include "spdlog/details/synchronous_factory.h" - #include #include #include diff --git a/include/spdlog/sinks/dist_sink.h b/include/spdlog/sinks/dist_sink.h index c7f207d7..8f931cf7 100644 --- a/include/spdlog/sinks/dist_sink.h +++ b/include/spdlog/sinks/dist_sink.h @@ -45,6 +45,11 @@ public: sinks_ = std::move(sinks); } + std::vector> &sinks() + { + return sinks_; + } + protected: void sink_it_(const details::log_msg &msg) override { diff --git a/include/spdlog/spdlog-inl.h b/include/spdlog/spdlog-inl.h index 5f6c8fb1..bbfb6e24 100644 --- a/include/spdlog/spdlog-inl.h +++ b/include/spdlog/spdlog-inl.h @@ -32,6 +32,21 @@ SPDLOG_INLINE void set_pattern(std::string pattern, pattern_time_type time_type) set_formatter(std::unique_ptr(new pattern_formatter(std::move(pattern), time_type))); } +SPDLOG_INLINE void enable_backtrace(size_t n_messages) +{ + details::registry::instance().enable_backtrace(n_messages); +} + +SPDLOG_INLINE void disable_backtrace() +{ + details::registry::instance().disable_backtrace(); +} + +SPDLOG_INLINE void dump_backtrace() +{ + default_logger_raw()->dump_backtrace(); +} + SPDLOG_INLINE void set_level(level::level_enum log_level) { details::registry::instance().set_level(log_level); diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index b4996688..72ba8974 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -60,6 +60,15 @@ void set_formatter(std::unique_ptr formatter); // example: spdlog::set_pattern("%Y-%m-%d %H:%M:%S.%e %l : %v"); void set_pattern(std::string pattern, pattern_time_type time_type = pattern_time_type::local); +// enable global backtrace support +void enable_backtrace(size_t n_messages); + +// disable global backtrace support +void disable_backtrace(); + +// call dump backtrace on default logger +void dump_backtrace(); + // Set global logging level void set_level(level::level_enum log_level); @@ -276,12 +285,7 @@ inline void critical(wstring_view_t fmt, const Args &... args) // SPDLOG_LEVEL_OFF // -#define SPDLOG_LOGGER_CALL(logger, level, ...) \ - do \ - { \ - if (logger->should_log(level)) \ - logger->force_log(spdlog::source_loc{__FILE__, __LINE__, SPDLOG_FUNCTION}, level, __VA_ARGS__); \ - } while (0) +#define SPDLOG_LOGGER_CALL(logger, level, ...) logger->log(spdlog::source_loc{__FILE__, __LINE__, SPDLOG_FUNCTION}, level, __VA_ARGS__); #if SPDLOG_ACTIVE_LEVEL <= SPDLOG_LEVEL_TRACE #define SPDLOG_LOGGER_TRACE(logger, ...) SPDLOG_LOGGER_CALL(logger, spdlog::level::trace, __VA_ARGS__) diff --git a/src/spdlog.cpp b/src/spdlog.cpp index be91412d..d30665aa 100644 --- a/src/spdlog.cpp +++ b/src/spdlog.cpp @@ -6,7 +6,6 @@ #endif #include -#include #include "spdlog/details/null_mutex.h" #include "spdlog/async.h" diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 0c64ba43..6a1fe138 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -23,7 +23,8 @@ set(SPDLOG_UTESTS_SOURCES test_sink.h test_fmt_helper.cpp test_stdout_api.cpp - test_dup_filter.cpp) + test_dup_filter.cpp + test_backtrace.cpp) if(NOT SPDLOG_NO_EXCEPTIONS) list(APPEND SPDLOG_UTESTS_SOURCES test_errors.cpp) diff --git a/tests/test_backtrace.cpp b/tests/test_backtrace.cpp new file mode 100644 index 00000000..89f4426d --- /dev/null +++ b/tests/test_backtrace.cpp @@ -0,0 +1,65 @@ +#include "includes.h" +#include "test_sink.h" +#include "spdlog/async.h" + +TEST_CASE("bactrace1", "[bactrace]") +{ + + using spdlog::sinks::test_sink_st; + auto test_sink = std::make_shared(); + size_t backtrace_size = 5; + + spdlog::logger logger("test-backtrace", test_sink); + logger.set_pattern("%v"); + logger.enable_backtrace(backtrace_size); + + logger.info("info message"); + for (int i = 0; i < 100; i++) + logger.debug("debug message {}", i); + + REQUIRE(test_sink->lines().size() == 1); + REQUIRE(test_sink->lines()[0] == "info message"); + + logger.dump_backtrace(); + REQUIRE(test_sink->lines().size() == backtrace_size + 3); + REQUIRE(test_sink->lines()[1] == "****************** Backtrace Start ******************"); + REQUIRE(test_sink->lines()[2] == "debug message 95"); + REQUIRE(test_sink->lines()[3] == "debug message 96"); + REQUIRE(test_sink->lines()[4] == "debug message 97"); + REQUIRE(test_sink->lines()[5] == "debug message 98"); + REQUIRE(test_sink->lines()[6] == "debug message 99"); + REQUIRE(test_sink->lines()[7] == "****************** Backtrace End ********************"); +} + +TEST_CASE("bactrace-async", "[bactrace]") +{ + using spdlog::sinks::test_sink_mt; + auto test_sink = std::make_shared(); + using spdlog::details::os::sleep_for_millis; + + size_t backtrace_size = 5; + + spdlog::init_thread_pool(120, 1); + auto logger = std::make_shared("test-bactrace-async", test_sink, spdlog::thread_pool()); + logger->set_pattern("%v"); + logger->enable_backtrace(backtrace_size); + + logger->info("info message"); + for (int i = 0; i < 100; i++) + logger->debug("debug message {}", i); + + sleep_for_millis(10); + REQUIRE(test_sink->lines().size() == 1); + REQUIRE(test_sink->lines()[0] == "info message"); + + logger->dump_backtrace(); + sleep_for_millis(100); // give time for the async dump to complete + REQUIRE(test_sink->lines().size() == backtrace_size + 3); + REQUIRE(test_sink->lines()[1] == "****************** Backtrace Start ******************"); + REQUIRE(test_sink->lines()[2] == "debug message 95"); + REQUIRE(test_sink->lines()[3] == "debug message 96"); + REQUIRE(test_sink->lines()[4] == "debug message 97"); + REQUIRE(test_sink->lines()[5] == "debug message 98"); + REQUIRE(test_sink->lines()[6] == "debug message 99"); + REQUIRE(test_sink->lines()[7] == "****************** Backtrace End ********************"); +} diff --git a/tests/test_misc.cpp b/tests/test_misc.cpp index 7400dd8f..e5bc3b43 100644 --- a/tests/test_misc.cpp +++ b/tests/test_misc.cpp @@ -92,47 +92,6 @@ TEST_CASE("periodic flush", "[periodic_flush]") spdlog::drop_all(); } -TEST_CASE("clone-logger", "[clone]") -{ - using namespace spdlog; - - auto logger = spdlog::create("orig"); - auto cloned = logger->clone("clone"); - - REQUIRE(cloned->name() == "clone"); - REQUIRE(logger->sinks() == cloned->sinks()); - REQUIRE(logger->level() == cloned->level()); - REQUIRE(logger->flush_level() == cloned->flush_level()); - logger->info("Some message 1"); - cloned->info("Some message 2"); - - auto test_sink = std::static_pointer_cast(cloned->sinks()[0]); - - spdlog::drop_all(); -} - -TEST_CASE("clone async", "[clone]") -{ - using namespace spdlog; - - auto logger = spdlog::create_async("orig"); - auto cloned = logger->clone("clone"); - - REQUIRE(cloned->name() == "clone"); - REQUIRE(logger->sinks() == cloned->sinks()); - REQUIRE(logger->level() == cloned->level()); - REQUIRE(logger->flush_level() == cloned->flush_level()); - - logger->info("Some message 1"); - cloned->info("Some message 2"); - - spdlog::details::os::sleep_for_millis(10); - - auto test_sink = std::static_pointer_cast(cloned->sinks()[0]); - - spdlog::drop_all(); -} - #include "spdlog/fmt/bin_to_hex.h" TEST_CASE("to_hex", "[to_hex]") diff --git a/tests/test_sink.h b/tests/test_sink.h index ae08e980..08945a85 100644 --- a/tests/test_sink.h +++ b/tests/test_sink.h @@ -7,7 +7,7 @@ #include "spdlog/details/null_mutex.h" #include "spdlog/sinks/base_sink.h" - +#include "spdlog/fmt/fmt.h" #include #include #include @@ -18,6 +18,8 @@ namespace sinks { template class test_sink : public base_sink { + const size_t lines_to_save = 100; + public: size_t msg_counter() { @@ -33,12 +35,28 @@ public: void set_delay(std::chrono::milliseconds delay) { + std::lock_guard lock(base_sink::mutex_); delay_ = delay; } -protected: - void sink_it_(const details::log_msg &) override + // return last output without the eol + std::vector lines() { + std::lock_guard lock(base_sink::mutex_); + return lines_; + } + +protected: + void sink_it_(const details::log_msg &msg) override + { + fmt::memory_buffer formatted; + base_sink::formatter_->format(msg, formatted); + // save the line without the eol + auto eol_len = strlen(details::os::default_eol); + if (lines_.size() < lines_to_save) + { + lines_.emplace_back(formatted.begin(), formatted.end() - eol_len); + } msg_counter_++; std::this_thread::sleep_for(delay_); } @@ -47,9 +65,11 @@ protected: { flush_counter_++; } + size_t msg_counter_{0}; size_t flush_counter_{0}; std::chrono::milliseconds delay_{std::chrono::milliseconds::zero()}; + std::vector lines_; }; using test_sink_mt = test_sink;