- Implement a pool to store dyn arg store objects in srslog to avoid allocations when passing arguments to the backend.

- Use string views inside the log formatters to avoid allocations.
- Avoid a std::string when using fmt::vsprintf, instead favour fmt::vprintf.
master
faluco 4 years ago committed by faluco
parent 1a0891df51
commit e8395c7474

@ -13,6 +13,8 @@
#ifndef SRSLOG_DETAIL_LOG_BACKEND_H #ifndef SRSLOG_DETAIL_LOG_BACKEND_H
#define SRSLOG_DETAIL_LOG_BACKEND_H #define SRSLOG_DETAIL_LOG_BACKEND_H
#include "srsran/srslog/bundled/fmt/printf.h"
namespace srslog { namespace srslog {
namespace detail { namespace detail {
@ -31,6 +33,9 @@ public:
/// NOTE: Calling this function more than once has no side effects. /// NOTE: Calling this function more than once has no side effects.
virtual void start() = 0; virtual void start() = 0;
/// Allocates a dyn_arg_store and returns a pointer to it on success, otherwise returns nullptr.
virtual fmt::dynamic_format_arg_store<fmt::printf_context>* alloc_arg_store() = 0;
/// Pushes a log entry into the backend. Returns true on success, otherwise /// Pushes a log entry into the backend. Returns true on success, otherwise
/// false. /// false.
virtual bool push(log_entry&& entry) = 0; virtual bool push(log_entry&& entry) = 0;

@ -34,14 +34,14 @@ struct log_context {
/// Metadata fields carried for each log entry. /// Metadata fields carried for each log entry.
struct log_entry_metadata { struct log_entry_metadata {
std::chrono::high_resolution_clock::time_point tp; std::chrono::high_resolution_clock::time_point tp;
log_context context; log_context context;
const char* fmtstring; const char* fmtstring;
fmt::dynamic_format_arg_store<fmt::printf_context> store; fmt::dynamic_format_arg_store<fmt::printf_context>* store;
std::string log_name; std::string log_name;
char log_tag; char log_tag;
small_str_buffer small_str; small_str_buffer small_str;
std::vector<uint8_t> hex_dump; std::vector<uint8_t> hex_dump;
}; };
} // namespace detail } // namespace detail

@ -0,0 +1,21 @@
/**
*
* \section COPYRIGHT
*
* Copyright 2013-2021 Software Radio Systems Limited
*
* By using this file, you agree to the terms and conditions set
* forth in the LICENSE file which can be found at the top level of
* the distribution.
*
*/
#ifndef SRSLOG_DETAIL_SUPPORT_BACKEND_CAPACITY_H
#define SRSLOG_DETAIL_SUPPORT_BACKEND_CAPACITY_H
/// Take this default value if users did not specify any custom size.
#ifndef SRSLOG_QUEUE_CAPACITY
#define SRSLOG_QUEUE_CAPACITY 8192
#endif
#endif // SRSLOG_DETAIL_SUPPORT_BACKEND_CAPACITY_H

@ -0,0 +1,78 @@
/**
*
* \section COPYRIGHT
*
* Copyright 2013-2021 Software Radio Systems Limited
*
* By using this file, you agree to the terms and conditions set
* forth in the LICENSE file which can be found at the top level of
* the distribution.
*
*/
#ifndef SRSLOG_DETAIL_SUPPORT_DYN_ARG_STORE_POOL_H
#define SRSLOG_DETAIL_SUPPORT_DYN_ARG_STORE_POOL_H
#include "srsran/srslog/bundled/fmt/printf.h"
#include "srsran/srslog/detail/support/backend_capacity.h"
namespace srslog {
namespace detail {
/// Keeps a pool of dynamic_format_arg_store objects. The main reason for this class is that the arg store objects are
/// implemented with std::vectors, so we want to avoid allocating memory each time we create a new object. Instead,
/// reserve memory for each vector during initialization and recycle the objects.
class dyn_arg_store_pool
{
public:
dyn_arg_store_pool()
{
pool.resize(SRSLOG_QUEUE_CAPACITY);
for (auto& elem : pool) {
// Reserve for 10 normal and 2 named arguments.
elem.reserve(10, 2);
}
free_list.reserve(SRSLOG_QUEUE_CAPACITY);
for (auto& elem : pool) {
free_list.push_back(&elem);
}
}
/// Returns a pointer to a free dyn arg store object, otherwise returns nullptr.
fmt::dynamic_format_arg_store<fmt::printf_context>* alloc()
{
scoped_lock lock(m);
if (free_list.empty()) {
return nullptr;
}
auto* p = free_list.back();
free_list.pop_back();
return p;
}
/// Deallocate the given dyn arg store object returning it to the pool.
void dealloc(fmt::dynamic_format_arg_store<fmt::printf_context>* p)
{
if (!p) {
return;
}
scoped_lock lock(m);
p->clear();
free_list.push_back(p);
}
private:
std::vector<fmt::dynamic_format_arg_store<fmt::printf_context> > pool;
std::vector<fmt::dynamic_format_arg_store<fmt::printf_context>*> free_list;
mutable mutex m;
};
} // namespace detail
} // namespace srslog
#endif // SRSLOG_DETAIL_SUPPORT_DYN_ARG_STORE_POOL_H

@ -13,13 +13,10 @@
#ifndef SRSLOG_DETAIL_SUPPORT_WORK_QUEUE_H #ifndef SRSLOG_DETAIL_SUPPORT_WORK_QUEUE_H
#define SRSLOG_DETAIL_SUPPORT_WORK_QUEUE_H #define SRSLOG_DETAIL_SUPPORT_WORK_QUEUE_H
#include "srsran/srslog/detail/support/backend_capacity.h"
#include "srsran/srslog/detail/support/thread_utils.h" #include "srsran/srslog/detail/support/thread_utils.h"
#include <queue> #include <queue>
#ifndef SRSLOG_QUEUE_CAPACITY
#define SRSLOG_QUEUE_CAPACITY 8192
#endif
namespace srslog { namespace srslog {
namespace detail { namespace detail {
@ -30,9 +27,9 @@ namespace detail {
template <typename T, size_t capacity = SRSLOG_QUEUE_CAPACITY> template <typename T, size_t capacity = SRSLOG_QUEUE_CAPACITY>
class work_queue class work_queue
{ {
std::queue<T> queue; std::queue<T> queue;
mutable condition_variable cond_var; mutable condition_variable cond_var;
static constexpr size_t threshold = capacity * 0.98; static constexpr size_t threshold = capacity * 0.98;
public: public:
work_queue() = default; work_queue() = default;

@ -34,7 +34,7 @@ struct metric_value_formatter {
/// Default metric value formatter. Users that want to override this behaviour /// Default metric value formatter. Users that want to override this behaviour
/// should add an specialization of the metric they want to customize. /// should add an specialization of the metric they want to customize.
template <typename Ty, typename Name, typename Units> template <typename Ty, typename Name, typename Units>
struct metric_value_formatter<metric<Ty, Name, Units>> { struct metric_value_formatter<metric<Ty, Name, Units> > {
template <typename T> template <typename T>
void format(const T& v, fmt::memory_buffer& buffer) void format(const T& v, fmt::memory_buffer& buffer)
{ {
@ -59,54 +59,38 @@ public:
virtual std::unique_ptr<log_formatter> clone() const = 0; virtual std::unique_ptr<log_formatter> clone() const = 0;
/// Formats the log entry into the input buffer. /// Formats the log entry into the input buffer.
virtual void format(detail::log_entry_metadata&& metadata, virtual void format(detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) = 0;
fmt::memory_buffer& buffer) = 0;
/// Formats the context and log entry into the input buffer. /// Formats the context and log entry into the input buffer.
template <typename... Ts> template <typename... Ts>
void format_ctx(const srslog::context<Ts...>& ctx, void format_ctx(const srslog::context<Ts...>& ctx, detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer)
detail::log_entry_metadata&& metadata,
fmt::memory_buffer& buffer)
{ {
format_context_begin(metadata, ctx.name(), sizeof...(Ts), buffer); format_context_begin(metadata, ctx.name(), sizeof...(Ts), buffer);
iterate_tuple(ctx.contents(), iterate_tuple(ctx.contents(), 1, buffer, detail::make_index_sequence<sizeof...(Ts)>{});
1,
buffer,
detail::make_index_sequence<sizeof...(Ts)>{});
format_context_end(metadata, ctx.name(), buffer); format_context_end(metadata, ctx.name(), buffer);
} }
private: private:
/// Processes all elements in a tuple. /// Processes all elements in a tuple.
template <typename... Ts, std::size_t... Is> template <typename... Ts, std::size_t... Is>
void iterate_tuple(const std::tuple<Ts...>& t, void
unsigned level, iterate_tuple(const std::tuple<Ts...>& t, unsigned level, fmt::memory_buffer& buffer, detail::index_sequence<Is...>)
fmt::memory_buffer& buffer,
detail::index_sequence<Is...>)
{ {
(void)std::initializer_list<int>{ (void)std::initializer_list<int>{(process_element(std::get<Is>(t), level, buffer), 0)...};
(process_element(std::get<Is>(t), level, buffer), 0)...};
} }
/// Processes the input metric set. /// Processes the input metric set.
template <typename Name, typename... Ts> template <typename Name, typename... Ts>
void process_element(const metric_set<Name, Ts...>& ms, void process_element(const metric_set<Name, Ts...>& ms, unsigned level, fmt::memory_buffer& buffer)
unsigned level,
fmt::memory_buffer& buffer)
{ {
format_metric_set_begin(ms.name(), sizeof...(Ts), level, buffer); format_metric_set_begin(ms.name(), sizeof...(Ts), level, buffer);
iterate_tuple(ms.contents(), iterate_tuple(ms.contents(), level + 1, buffer, detail::make_index_sequence<sizeof...(Ts)>{});
level + 1,
buffer,
detail::make_index_sequence<sizeof...(Ts)>{});
format_metric_set_end(ms.name(), level, buffer); format_metric_set_end(ms.name(), level, buffer);
} }
/// Processes the input metric list. /// Processes the input metric list.
template <typename Name, typename T> template <typename Name, typename T>
void process_element(const metric_list<Name, T>& list, void process_element(const metric_list<Name, T>& list, unsigned level, fmt::memory_buffer& buffer)
unsigned level,
fmt::memory_buffer& buffer)
{ {
format_list_begin(list.name(), list.size(), level, buffer); format_list_begin(list.name(), list.size(), level, buffer);
for (const auto& elem : list) { for (const auto& elem : list) {
@ -117,16 +101,13 @@ private:
/// Processes the input metric. /// Processes the input metric.
template <typename Ty, typename Name, typename Units> template <typename Ty, typename Name, typename Units>
void process_element(const metric<Ty, Name, Units>& t, void process_element(const metric<Ty, Name, Units>& t, unsigned level, fmt::memory_buffer& buffer)
unsigned level,
fmt::memory_buffer& buffer)
{ {
fmt::memory_buffer value; fmt::memory_buffer value;
metric_value_formatter<typename std::decay<decltype(t)>::type>{}.format( metric_value_formatter<typename std::decay<decltype(t)>::type>{}.format(t.value, value);
t.value, value); value.push_back('\0');
format_metric( format_metric(t.name(), value.data(), t.units(), t.kind(), level, buffer);
t.name(), fmt::to_string(value), t.units(), t.kind(), level, buffer);
} }
private: private:
@ -137,46 +118,37 @@ private:
/// This callback gets called at the beginning of the context formatting /// This callback gets called at the beginning of the context formatting
/// algorithm. /// algorithm.
virtual void format_context_begin(const detail::log_entry_metadata& md, virtual void format_context_begin(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
unsigned size, unsigned size,
fmt::memory_buffer& buffer) = 0; fmt::memory_buffer& buffer) = 0;
/// This callback gets called at the end of the context formatting algorithm. /// This callback gets called at the end of the context formatting algorithm.
virtual void format_context_end(const detail::log_entry_metadata& md, virtual void
const std::string& ctx_name, format_context_end(const detail::log_entry_metadata& md, fmt::string_view ctx_name, fmt::memory_buffer& buffer) = 0;
fmt::memory_buffer& buffer) = 0;
/// This callback gets called at the beginning of a metric set formatting /// This callback gets called at the beginning of a metric set formatting
/// procedure. /// procedure.
virtual void format_metric_set_begin(const std::string& set_name, virtual void
unsigned size, format_metric_set_begin(fmt::string_view set_name, unsigned size, unsigned level, fmt::memory_buffer& buffer) = 0;
unsigned level,
fmt::memory_buffer& buffer) = 0;
/// This callback gets called at the beginning of a metric set formatting end. /// This callback gets called at the beginning of a metric set formatting end.
virtual void format_metric_set_end(const std::string& set_name, virtual void format_metric_set_end(fmt::string_view set_name, unsigned level, fmt::memory_buffer& buffer) = 0;
unsigned level,
fmt::memory_buffer& buffer) = 0;
/// This callback gets called at the beginning of a metric list formatting /// This callback gets called at the beginning of a metric list formatting
/// procedure. /// procedure.
virtual void format_list_begin(const std::string& list_name, virtual void
unsigned size, format_list_begin(fmt::string_view list_name, unsigned size, unsigned level, fmt::memory_buffer& buffer) = 0;
unsigned level,
fmt::memory_buffer& buffer) = 0;
/// This callback gets called at the end of a metric list formatting /// This callback gets called at the end of a metric list formatting
/// procedure. /// procedure.
virtual void format_list_end(const std::string& list_name, virtual void format_list_end(fmt::string_view list_name, unsigned level, fmt::memory_buffer& buffer) = 0;
unsigned level,
fmt::memory_buffer& buffer) = 0;
/// This callback gets called for each metric. /// This callback gets called for each metric.
virtual void format_metric(const std::string& metric_name, virtual void format_metric(fmt::string_view metric_name,
const std::string& metric_value, fmt::string_view metric_value,
const std::string& metric_units, fmt::string_view metric_units,
metric_kind kind, metric_kind kind,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) = 0; fmt::memory_buffer& buffer) = 0;
}; };

@ -47,14 +47,9 @@ struct log_channel_config {
class log_channel class log_channel
{ {
public: public:
log_channel(std::string id, sink& s, detail::log_backend& backend) : log_channel(std::string id, sink& s, detail::log_backend& backend) : log_channel(std::move(id), s, backend, {}) {}
log_channel(std::move(id), s, backend, {})
{}
log_channel(std::string id, log_channel(std::string id, sink& s, detail::log_backend& backend, log_channel_config config) :
sink& s,
detail::log_backend& backend,
log_channel_config config) :
log_id(std::move(id)), log_id(std::move(id)),
log_sink(s), log_sink(s),
backend(backend), backend(backend),
@ -96,91 +91,87 @@ public:
} }
// Populate the store with all incoming arguments. // Populate the store with all incoming arguments.
fmt::dynamic_format_arg_store<fmt::printf_context> store; auto* store = backend.alloc_arg_store();
(void)std::initializer_list<int>{ if (!store) {
(store.push_back(std::forward<Args>(args)), 0)...}; return;
}
(void)std::initializer_list<int>{(store->push_back(std::forward<Args>(args)), 0)...};
// Send the log entry to the backend. // Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter(); log_formatter& formatter = log_sink.get_formatter();
detail::log_entry entry = { detail::log_entry entry = {&log_sink,
&log_sink, [&formatter](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {
[&formatter](detail::log_entry_metadata&& metadata, formatter.format(std::move(metadata), buffer);
fmt::memory_buffer& buffer) { },
formatter.format(std::move(metadata), buffer); {std::chrono::high_resolution_clock::now(),
}, {ctx_value, should_print_context},
{std::chrono::high_resolution_clock::now(), fmtstr,
{ctx_value, should_print_context}, store,
fmtstr, log_name,
std::move(store), log_tag,
log_name, small_str_buffer()}};
log_tag,
small_str_buffer()}};
backend.push(std::move(entry)); backend.push(std::move(entry));
} }
/// Builds the provided log entry and passes it to the backend. When the /// Builds the provided log entry and passes it to the backend. When the
/// channel is disabled the log entry will be discarded. /// channel is disabled the log entry will be discarded.
void operator()(small_str_buffer &&str) void operator()(small_str_buffer&& str)
{ {
if (!enabled()) { if (!enabled()) {
return; return;
} }
// Send the log entry to the backend. // Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter(); log_formatter& formatter = log_sink.get_formatter();
detail::log_entry entry = { detail::log_entry entry = {&log_sink,
&log_sink, [&formatter](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {
[&formatter](detail::log_entry_metadata&& metadata, formatter.format(std::move(metadata), buffer);
fmt::memory_buffer& buffer) { },
formatter.format(std::move(metadata), buffer); {std::chrono::high_resolution_clock::now(),
}, {ctx_value, should_print_context},
{std::chrono::high_resolution_clock::now(), nullptr,
{ctx_value, should_print_context}, nullptr,
nullptr, log_name,
{}, log_tag,
log_name, std::move(str)}};
log_tag,
std::move(str)}};
backend.push(std::move(entry)); backend.push(std::move(entry));
} }
/// Builds the provided log entry and passes it to the backend. When the /// Builds the provided log entry and passes it to the backend. When the
/// channel is disabled the log entry will be discarded. /// channel is disabled the log entry will be discarded.
template <typename... Args> template <typename... Args>
void operator()(const uint8_t* buffer, void operator()(const uint8_t* buffer, size_t len, const char* fmtstr, Args&&... args)
size_t len,
const char* fmtstr,
Args&&... args)
{ {
if (!enabled()) { if (!enabled()) {
return; return;
} }
// Populate the store with all incoming arguments. // Populate the store with all incoming arguments.
fmt::dynamic_format_arg_store<fmt::printf_context> store; auto* store = backend.alloc_arg_store();
(void)std::initializer_list<int>{ if (!store) {
(store.push_back(std::forward<Args>(args)), 0)...}; return;
}
(void)std::initializer_list<int>{(store->push_back(std::forward<Args>(args)), 0)...};
// Calculate the length to capture in the buffer. // Calculate the length to capture in the buffer.
if (hex_max_size >= 0) if (hex_max_size >= 0) {
len = std::min<size_t>(len, hex_max_size); len = std::min<size_t>(len, hex_max_size);
}
// Send the log entry to the backend. // Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter(); log_formatter& formatter = log_sink.get_formatter();
detail::log_entry entry = { detail::log_entry entry = {&log_sink,
&log_sink, [&formatter](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {
[&formatter](detail::log_entry_metadata&& metadata, formatter.format(std::move(metadata), buffer);
fmt::memory_buffer& buffer) { },
formatter.format(std::move(metadata), buffer); {std::chrono::high_resolution_clock::now(),
}, {ctx_value, should_print_context},
{std::chrono::high_resolution_clock::now(), fmtstr,
{ctx_value, should_print_context}, store,
fmtstr, log_name,
std::move(store), log_tag,
log_name, small_str_buffer(),
log_tag, std::vector<uint8_t>(buffer, buffer + len)}};
small_str_buffer(),
std::vector<uint8_t>(buffer, buffer + len)}};
backend.push(std::move(entry)); backend.push(std::move(entry));
} }
@ -194,20 +185,18 @@ public:
} }
// Send the log entry to the backend. // Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter(); log_formatter& formatter = log_sink.get_formatter();
detail::log_entry entry = { detail::log_entry entry = {&log_sink,
&log_sink, [&formatter, ctx](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {
[&formatter, ctx](detail::log_entry_metadata&& metadata, formatter.format_ctx(ctx, std::move(metadata), buffer);
fmt::memory_buffer& buffer) { },
formatter.format_ctx(ctx, std::move(metadata), buffer); {std::chrono::high_resolution_clock::now(),
}, {ctx_value, should_print_context},
{std::chrono::high_resolution_clock::now(), nullptr,
{ctx_value, should_print_context}, nullptr,
nullptr, log_name,
{}, log_tag,
log_name, small_str_buffer()}};
log_tag,
small_str_buffer()}};
backend.push(std::move(entry)); backend.push(std::move(entry));
} }
@ -221,38 +210,38 @@ public:
} }
// Populate the store with all incoming arguments. // Populate the store with all incoming arguments.
fmt::dynamic_format_arg_store<fmt::printf_context> store; auto* store = backend.alloc_arg_store();
(void)std::initializer_list<int>{ if (!store) {
(store.push_back(std::forward<Args>(args)), 0)...}; return;
}
(void)std::initializer_list<int>{(store->push_back(std::forward<Args>(args)), 0)...};
// Send the log entry to the backend. // Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter(); log_formatter& formatter = log_sink.get_formatter();
detail::log_entry entry = { detail::log_entry entry = {&log_sink,
&log_sink, [&formatter, ctx](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {
[&formatter, ctx](detail::log_entry_metadata&& metadata, formatter.format_ctx(ctx, std::move(metadata), buffer);
fmt::memory_buffer& buffer) { },
formatter.format_ctx(ctx, std::move(metadata), buffer); {std::chrono::high_resolution_clock::now(),
}, {ctx_value, should_print_context},
{std::chrono::high_resolution_clock::now(), fmtstr,
{ctx_value, should_print_context}, store,
fmtstr, log_name,
std::move(store), log_tag,
log_name, small_str_buffer()}};
log_tag,
small_str_buffer()}};
backend.push(std::move(entry)); backend.push(std::move(entry));
} }
private: private:
const std::string log_id; const std::string log_id;
sink& log_sink; sink& log_sink;
detail::log_backend& backend; detail::log_backend& backend;
const std::string log_name; const std::string log_name;
const char log_tag; const char log_tag;
const bool should_print_context; const bool should_print_context;
detail::shared_variable<uint32_t> ctx_value; detail::shared_variable<uint32_t> ctx_value;
detail::shared_variable<int> hex_max_size; detail::shared_variable<int> hex_max_size;
detail::shared_variable<bool> is_enabled; detail::shared_variable<bool> is_enabled;
}; };
} // namespace srslog } // namespace srslog

@ -95,8 +95,14 @@ void backend_worker::process_log_entry(detail::log_entry&& entry)
if (entry.metadata.small_str.size()) { if (entry.metadata.small_str.size()) {
entry.metadata.fmtstring = entry.metadata.small_str.data(); entry.metadata.fmtstring = entry.metadata.small_str.data();
} }
// Save the pointer before moving the entry.
auto* arg_store = entry.metadata.store;
entry.format_func(std::move(entry.metadata), fmt_buffer); entry.format_func(std::move(entry.metadata), fmt_buffer);
arg_pool.dealloc(arg_store);
if (auto err_str = entry.s->write({fmt_buffer.data(), fmt_buffer.size()})) { if (auto err_str = entry.s->write({fmt_buffer.data(), fmt_buffer.size()})) {
err_handler(err_str.get_error()); err_handler(err_str.get_error());
} }

@ -14,6 +14,7 @@
#define SRSLOG_BACKEND_WORKER_H #define SRSLOG_BACKEND_WORKER_H
#include "srsran/srslog/detail/log_entry.h" #include "srsran/srslog/detail/log_entry.h"
#include "srsran/srslog/detail/support/dyn_arg_store_pool.h"
#include "srsran/srslog/detail/support/work_queue.h" #include "srsran/srslog/detail/support/work_queue.h"
#include "srsran/srslog/shared_types.h" #include "srsran/srslog/shared_types.h"
#include <mutex> #include <mutex>
@ -31,8 +32,8 @@ class backend_worker
static constexpr unsigned sleep_period_ms = 500; static constexpr unsigned sleep_period_ms = 500;
public: public:
explicit backend_worker(detail::work_queue<detail::log_entry>& queue) : explicit backend_worker(detail::work_queue<detail::log_entry>& queue, detail::dyn_arg_store_pool& arg_pool) :
queue(queue), running_flag(false) queue(queue), arg_pool(arg_pool), running_flag(false)
{} {}
backend_worker(const backend_worker&) = delete; backend_worker(const backend_worker&) = delete;
@ -94,23 +95,21 @@ private:
void report_queue_on_full_once() void report_queue_on_full_once()
{ {
if (queue.is_almost_full()) { if (queue.is_almost_full()) {
err_handler( err_handler(fmt::format("The backend queue size is about to reach its maximum "
fmt::format("The backend queue size is about to reach its maximum " "capacity of {} elements, new log entries will get "
"capacity of {} elements, new log entries will get " "discarded.\nConsider increasing the queue capacity.",
"discarded.\nConsider increasing the queue capacity.", queue.get_capacity()));
queue.get_capacity()));
err_handler = [](const std::string&) {}; err_handler = [](const std::string&) {};
} }
} }
private: private:
detail::work_queue<detail::log_entry>& queue; detail::work_queue<detail::log_entry>& queue;
detail::shared_variable<bool> running_flag; detail::dyn_arg_store_pool& arg_pool;
error_handler err_handler = [](const std::string& error) { detail::shared_variable<bool> running_flag;
fmt::print(stderr, "srsLog error - {}\n", error); error_handler err_handler = [](const std::string& error) { fmt::print(stderr, "srsLog error - {}\n", error); };
}; std::once_flag start_once_flag;
std::once_flag start_once_flag; std::thread worker_thread;
std::thread worker_thread;
fmt::memory_buffer fmt_buffer; fmt::memory_buffer fmt_buffer;
}; };

@ -20,28 +20,33 @@ std::unique_ptr<log_formatter> json_formatter::clone() const
return std::unique_ptr<log_formatter>(new json_formatter); return std::unique_ptr<log_formatter>(new json_formatter);
} }
void json_formatter::format(detail::log_entry_metadata&& metadata, void json_formatter::format(detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer)
fmt::memory_buffer& buffer)
{ {
fmt::format_to(buffer, fmt::format_to(buffer,
"{{\n" "{{\n"
" \"log_entry\": \"{}\"", " \"log_entry\": \"");
fmt::vsprintf(metadata.fmtstring, std::move(metadata.store))); if (metadata.fmtstring) {
if (metadata.store) {
fmt::basic_format_args<fmt::basic_printf_context_t<char> > args(*metadata.store);
fmt::vprintf(buffer, fmt::to_string_view(metadata.fmtstring), args);
fmt::format_to(buffer, fmt::to_string_view("\""));
} else {
fmt::format_to(buffer, "{}\"", metadata.fmtstring);
}
}
if (!metadata.hex_dump.empty()) { if (!metadata.hex_dump.empty()) {
fmt::format_to( fmt::format_to(
buffer, buffer, ",\n \"hex_dump\": \"{:02x}\"", fmt::join(metadata.hex_dump.cbegin(), metadata.hex_dump.cend(), " "));
",\n \"hex_dump\": \"{:02x}\"",
fmt::join(metadata.hex_dump.cbegin(), metadata.hex_dump.cend(), " "));
} }
fmt::format_to(buffer, "\n}}\n"); fmt::format_to(buffer, "\n}}\n");
} }
void json_formatter::format_context_begin(const detail::log_entry_metadata& md, void json_formatter::format_context_begin(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
unsigned size, unsigned size,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
assert(scope_stack.empty() && "Stack should be empty"); assert(scope_stack.empty() && "Stack should be empty");
assert(nest_level == 0 && "Nesting level should be 0"); assert(nest_level == 0 && "Nesting level should be 0");
@ -50,15 +55,20 @@ void json_formatter::format_context_begin(const detail::log_entry_metadata& md,
push_scope(size); push_scope(size);
if (md.fmtstring) { if (md.fmtstring) {
fmt::format_to(buffer, if (md.store) {
" \"log_entry\": \"{}\",\n", fmt::format_to(buffer, " \"log_entry\": \"");
fmt::vsprintf(md.fmtstring, std::move(md.store))); fmt::basic_format_args<fmt::basic_printf_context_t<char> > args(*md.store);
fmt::vprintf(buffer, fmt::to_string_view(md.fmtstring), args);
fmt::format_to(buffer, "\",\n");
} else {
fmt::format_to(buffer, " \"log_entry\": \"{}\",\n", md.fmtstring);
}
} }
} }
void json_formatter::format_context_end(const detail::log_entry_metadata& md, void json_formatter::format_context_end(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
pop_scope(); pop_scope();
fmt::format_to(buffer, "}}\n"); fmt::format_to(buffer, "}}\n");
@ -67,9 +77,9 @@ void json_formatter::format_context_end(const detail::log_entry_metadata& md,
assert(nest_level == 0 && "Nesting level should be 0"); assert(nest_level == 0 && "Nesting level should be 0");
} }
void json_formatter::format_metric_set_begin(const std::string& set_name, void json_formatter::format_metric_set_begin(fmt::string_view set_name,
unsigned size, unsigned size,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
// Arrays in JSON require an additional nesting level before inserting the // Arrays in JSON require an additional nesting level before inserting the
@ -90,29 +100,22 @@ void json_formatter::format_metric_set_begin(const std::string& set_name,
push_scope(size); push_scope(size);
} }
void json_formatter::format_metric_set_end(const std::string& set_name, void json_formatter::format_metric_set_end(fmt::string_view set_name, unsigned level, fmt::memory_buffer& buffer)
unsigned level,
fmt::memory_buffer& buffer)
{ {
pop_scope(); pop_scope();
fmt::format_to(buffer, fmt::format_to(buffer, "{: <{}}}}{}\n", ' ', indents(level), needs_comma() && !in_list_scope() ? "," : "");
"{: <{}}}}{}\n",
' ',
indents(level),
needs_comma() && !in_list_scope() ? "," : "");
if (in_list_scope()) { if (in_list_scope()) {
decrement_nest_level(); decrement_nest_level();
fmt::format_to( fmt::format_to(buffer, "{: <{}}}}{}\n", ' ', indents(level), needs_comma() ? "," : "");
buffer, "{: <{}}}}{}\n", ' ', indents(level), needs_comma() ? "," : "");
} }
} }
void json_formatter::format_metric(const std::string& metric_name, void json_formatter::format_metric(fmt::string_view metric_name,
const std::string& metric_value, fmt::string_view metric_value,
const std::string& metric_units, fmt::string_view metric_units,
metric_kind kind, metric_kind kind,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
consume_element(); consume_element();
@ -128,9 +131,9 @@ void json_formatter::format_metric(const std::string& metric_name,
needs_comma() ? "," : ""); needs_comma() ? "," : "");
} }
void json_formatter::format_list_begin(const std::string& list_name, void json_formatter::format_list_begin(fmt::string_view list_name,
unsigned size, unsigned size,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
consume_element(); consume_element();
@ -139,11 +142,8 @@ void json_formatter::format_list_begin(const std::string& list_name,
push_list_scope(size); push_list_scope(size);
} }
void json_formatter::format_list_end(const std::string& list_name, void json_formatter::format_list_end(fmt::string_view list_name, unsigned level, fmt::memory_buffer& buffer)
unsigned level,
fmt::memory_buffer& buffer)
{ {
pop_scope(); pop_scope();
fmt::format_to( fmt::format_to(buffer, "{: <{}}]{}\n", ' ', indents(level), needs_comma() ? "," : "");
buffer, "{: <{}}]{}\n", ' ', indents(level), needs_comma() ? "," : "");
} }

@ -29,42 +29,35 @@ public:
std::unique_ptr<log_formatter> clone() const override; std::unique_ptr<log_formatter> clone() const override;
void format(detail::log_entry_metadata&& metadata, void format(detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) override;
fmt::memory_buffer& buffer) override;
private: private:
void format_context_begin(const detail::log_entry_metadata& md, void format_context_begin(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
unsigned size, unsigned size,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
void format_context_end(const detail::log_entry_metadata& md, void format_context_end(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
void format_metric_set_begin(const std::string& set_name, void format_metric_set_begin(fmt::string_view set_name,
unsigned size, unsigned size,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
void format_metric_set_end(const std::string& set_name, void format_metric_set_end(fmt::string_view set_name, unsigned level, fmt::memory_buffer& buffer) override;
unsigned level,
fmt::memory_buffer& buffer) override;
void format_list_begin(const std::string& list_name, void
unsigned size, format_list_begin(fmt::string_view list_name, unsigned size, unsigned level, fmt::memory_buffer& buffer) override;
unsigned level,
fmt::memory_buffer& buffer) override;
void format_list_end(const std::string& list_name, void format_list_end(fmt::string_view list_name, unsigned level, fmt::memory_buffer& buffer) override;
unsigned level,
fmt::memory_buffer& buffer) override;
void format_metric(const std::string& metric_name, void format_metric(fmt::string_view metric_name,
const std::string& metric_value, fmt::string_view metric_value,
const std::string& metric_units, fmt::string_view metric_units,
metric_kind kind, metric_kind kind,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
/// Pushes a new entry in the scope stack. /// Pushes a new entry in the scope stack.
@ -118,9 +111,7 @@ private:
private: private:
/// Keeps track of some information about a JSON scope. /// Keeps track of some information about a JSON scope.
struct scope { struct scope {
scope(unsigned size, bool inside_list) : scope(unsigned size, bool inside_list) : size(size), inside_list(inside_list) {}
size(size), inside_list(inside_list)
{}
/// Number of elements this scope holds. /// Number of elements this scope holds.
unsigned size; unsigned size;
/// If true, indicates this scope belongs to a list. /// If true, indicates this scope belongs to a list.
@ -128,7 +119,7 @@ private:
}; };
private: private:
unsigned nest_level = 0; unsigned nest_level = 0;
std::vector<scope> scope_stack; std::vector<scope> scope_stack;
}; };

@ -23,39 +23,26 @@ std::unique_ptr<log_formatter> text_formatter::clone() const
/// Formats into a hex dump a range of elements, storing the result in the input /// Formats into a hex dump a range of elements, storing the result in the input
/// buffer. /// buffer.
static void format_hex_dump(const std::vector<uint8_t>& v, static void format_hex_dump(const std::vector<uint8_t>& v, fmt::memory_buffer& buffer)
fmt::memory_buffer& buffer)
{ {
if (v.empty()) {
return;
}
const size_t elements_per_line = 16; const size_t elements_per_line = 16;
for (auto i = v.cbegin(), e = v.cend(); i != e;) { for (auto i = v.cbegin(), e = v.cend(); i != e;) {
auto num_elements = auto num_elements = std::min<size_t>(elements_per_line, std::distance(i, e));
std::min<size_t>(elements_per_line, std::distance(i, e));
fmt::format_to(buffer, fmt::format_to(buffer, " {:04x}: {:02x}\n", std::distance(v.cbegin(), i), fmt::join(i, i + num_elements, " "));
" {:04x}: {:02x}\n",
std::distance(v.cbegin(), i),
fmt::join(i, i + num_elements, " "));
std::advance(i, num_elements); std::advance(i, num_elements);
} }
} }
/// Format the log metadata into the input buffer. /// Format the log metadata into the input buffer.
static void format_metadata(const detail::log_entry_metadata& metadata, static void format_metadata(const detail::log_entry_metadata& metadata, fmt::memory_buffer& buffer)
fmt::memory_buffer& buffer)
{ {
// Time stamp data preparation. // Time stamp data preparation.
std::tm current_time = std::tm current_time = fmt::gmtime(std::chrono::high_resolution_clock::to_time_t(metadata.tp));
fmt::gmtime(std::chrono::high_resolution_clock::to_time_t(metadata.tp)); auto us_fraction =
auto us_fraction = std::chrono::duration_cast<std::chrono::microseconds>( std::chrono::duration_cast<std::chrono::microseconds>(metadata.tp.time_since_epoch()).count() % 1000000u;
metadata.tp.time_since_epoch())
.count() %
1000000u;
fmt::format_to(buffer, "{:%H:%M:%S}.{:06} ", current_time, us_fraction); fmt::format_to(buffer, "{:%H:%M:%S}.{:06} ", current_time, us_fraction);
// Format optional fields if present. // Format optional fields if present.
@ -70,25 +57,30 @@ static void format_metadata(const detail::log_entry_metadata& metadata,
} }
} }
void text_formatter::format(detail::log_entry_metadata&& metadata, void text_formatter::format(detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer)
fmt::memory_buffer& buffer)
{ {
// Prefix first. // Prefix first.
format_metadata(metadata, buffer); format_metadata(metadata, buffer);
// Message formatting. // Message formatting.
fmt::format_to(buffer, if (metadata.fmtstring) {
"{}\n", if (metadata.store) {
fmt::vsprintf(metadata.fmtstring, std::move(metadata.store))); fmt::basic_format_args<fmt::basic_printf_context_t<char> > args(*metadata.store);
fmt::vprintf(buffer, fmt::to_string_view(metadata.fmtstring), args);
fmt::format_to(buffer, "\n");
} else {
fmt::format_to(buffer, "{}\n", metadata.fmtstring);
}
}
// Optional hex dump formatting. // Optional hex dump formatting.
format_hex_dump(metadata.hex_dump, buffer); format_hex_dump(metadata.hex_dump, buffer);
} }
void text_formatter::format_context_begin(const detail::log_entry_metadata& md, void text_formatter::format_context_begin(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
unsigned size, unsigned size,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
// Entries without a log message are printed using a richer format. // Entries without a log message are printed using a richer format.
do_one_line_ctx_format = md.fmtstring; do_one_line_ctx_format = md.fmtstring;
@ -104,35 +96,39 @@ void text_formatter::format_context_begin(const detail::log_entry_metadata& md,
} }
void text_formatter::format_context_end(const detail::log_entry_metadata& md, void text_formatter::format_context_end(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
if (!do_one_line_ctx_format) { if (!do_one_line_ctx_format) {
return; return;
} }
fmt::format_to(buffer, "]: {}\n", fmt::vsprintf(md.fmtstring, md.store)); if (md.store) {
fmt::format_to(buffer, "]: ");
fmt::basic_format_args<fmt::basic_printf_context_t<char> > args(*md.store);
fmt::vprintf(buffer, fmt::to_string_view(md.fmtstring), args);
fmt::format_to(buffer, "\n");
} else {
fmt::format_to(buffer, "]: {}\n", md.fmtstring);
}
assert(scope_stack.empty() && "Stack should be empty"); assert(scope_stack.empty() && "Stack should be empty");
} }
void text_formatter::format_metric_set_begin(const std::string& set_name, void text_formatter::format_metric_set_begin(fmt::string_view set_name,
unsigned size, unsigned size,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
if (do_one_line_ctx_format) { if (do_one_line_ctx_format) {
scope_stack.emplace_back(size, set_name); scope_stack.emplace_back(size, set_name.data());
fmt::format_to(buffer, "["); fmt::format_to(buffer, "[");
return; return;
} }
fmt::format_to( fmt::format_to(buffer, "{: <{}}> Set: {}\n", ' ', get_indents(level), set_name);
buffer, "{: <{}}> Set: {}\n", ' ', get_indents(level), set_name);
} }
void text_formatter::format_metric_set_end(const std::string& set_name, void text_formatter::format_metric_set_end(fmt::string_view set_name, unsigned level, fmt::memory_buffer& buffer)
unsigned level,
fmt::memory_buffer& buffer)
{ {
if (!do_one_line_ctx_format) { if (!do_one_line_ctx_format) {
return; return;
@ -142,11 +138,11 @@ void text_formatter::format_metric_set_end(const std::string& set_name,
fmt::format_to(buffer, "]"); fmt::format_to(buffer, "]");
} }
void text_formatter::format_metric(const std::string& metric_name, void text_formatter::format_metric(fmt::string_view metric_name,
const std::string& metric_value, fmt::string_view metric_value,
const std::string& metric_units, fmt::string_view metric_units,
metric_kind kind, metric_kind kind,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
if (do_one_line_ctx_format) { if (do_one_line_ctx_format) {
@ -156,7 +152,7 @@ void text_formatter::format_metric(const std::string& metric_name,
get_current_set_name(), get_current_set_name(),
metric_name, metric_name,
metric_value, metric_value,
metric_units.empty() ? "" : " ", metric_units.size() == 0 ? "" : " ",
metric_units, metric_units,
needs_comma() ? ", " : ""); needs_comma() ? ", " : "");
return; return;
@ -168,18 +164,17 @@ void text_formatter::format_metric(const std::string& metric_name,
get_indents(level), get_indents(level),
metric_name, metric_name,
metric_value, metric_value,
metric_units.empty() ? "" : " ", metric_units.size() == 0 ? "" : " ",
metric_units); metric_units);
} }
void text_formatter::format_list_begin(const std::string& list_name, void text_formatter::format_list_begin(fmt::string_view list_name,
unsigned size, unsigned size,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) fmt::memory_buffer& buffer)
{ {
if (do_one_line_ctx_format) { if (do_one_line_ctx_format) {
return; return;
} }
fmt::format_to( fmt::format_to(buffer, "{: <{}}> List: {}\n", ' ', get_indents(level), list_name);
buffer, "{: <{}}> List: {}\n", ' ', get_indents(level), list_name);
} }

@ -25,43 +25,35 @@ public:
std::unique_ptr<log_formatter> clone() const override; std::unique_ptr<log_formatter> clone() const override;
void format(detail::log_entry_metadata&& metadata, void format(detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) override;
fmt::memory_buffer& buffer) override;
private: private:
void format_context_begin(const detail::log_entry_metadata& md, void format_context_begin(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
unsigned size, unsigned size,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
void format_context_end(const detail::log_entry_metadata& md, void format_context_end(const detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
void format_metric_set_begin(const std::string& set_name, void format_metric_set_begin(fmt::string_view set_name,
unsigned size, unsigned size,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
void format_metric_set_end(const std::string& set_name, void format_metric_set_end(fmt::string_view set_name, unsigned level, fmt::memory_buffer& buffer) override;
unsigned level,
fmt::memory_buffer& buffer) override; void
format_list_begin(fmt::string_view list_name, unsigned size, unsigned level, fmt::memory_buffer& buffer) override;
void format_list_begin(const std::string& list_name,
unsigned size, void format_list_end(fmt::string_view list_name, unsigned level, fmt::memory_buffer& buffer) override {}
unsigned level,
fmt::memory_buffer& buffer) override; void format_metric(fmt::string_view metric_name,
fmt::string_view metric_value,
void format_list_end(const std::string& list_name, fmt::string_view metric_units,
unsigned level, metric_kind kind,
fmt::memory_buffer& buffer) override unsigned level,
{}
void format_metric(const std::string& metric_name,
const std::string& metric_value,
const std::string& metric_units,
metric_kind kind,
unsigned level,
fmt::memory_buffer& buffer) override; fmt::memory_buffer& buffer) override;
/// Returns the set name of current scope. /// Returns the set name of current scope.
@ -92,9 +84,7 @@ private:
private: private:
/// Keeps track of some state required for formatting. /// Keeps track of some state required for formatting.
struct scope { struct scope {
scope(unsigned size, std::string set_name) : scope(unsigned size, std::string set_name) : size(size), set_name(std::move(set_name)) {}
size(size), set_name(std::move(set_name))
{}
/// Number of elements this scope holds. /// Number of elements this scope holds.
unsigned size; unsigned size;
/// Set name in this scope. /// Set name in this scope.
@ -103,7 +93,7 @@ private:
private: private:
/// Flags that the formatting should take place into a single line. /// Flags that the formatting should take place into a single line.
bool do_one_line_ctx_format = false; bool do_one_line_ctx_format = false;
std::vector<scope> scope_stack; std::vector<scope> scope_stack;
}; };

@ -33,23 +33,28 @@ public:
bool push(detail::log_entry&& entry) override bool push(detail::log_entry&& entry) override
{ {
return queue.push(std::move(entry)); auto* arg_store = entry.metadata.store;
if (!queue.push(std::move(entry))) {
arg_pool.dealloc(arg_store);
return false;
}
return true;
} }
fmt::dynamic_format_arg_store<fmt::printf_context>* alloc_arg_store() override { return arg_pool.alloc(); }
bool is_running() const override { return worker.is_running(); } bool is_running() const override { return worker.is_running(); }
/// Installs the specified error handler into the backend worker. /// Installs the specified error handler into the backend worker.
void set_error_handler(error_handler err_handler) void set_error_handler(error_handler err_handler) { worker.set_error_handler(std::move(err_handler)); }
{
worker.set_error_handler(std::move(err_handler));
}
/// Stops the backend worker thread. /// Stops the backend worker thread.
void stop() { worker.stop(); } void stop() { worker.stop(); }
private: private:
detail::work_queue<detail::log_entry> queue; detail::work_queue<detail::log_entry> queue;
backend_worker worker{queue}; detail::dyn_arg_store_pool arg_pool;
backend_worker worker{queue, arg_pool};
}; };
} // namespace srslog } // namespace srslog

@ -198,6 +198,7 @@ void srslog::flush()
} }
detail::log_entry cmd; detail::log_entry cmd;
cmd.metadata.store = nullptr;
cmd.flush_cmd = std::unique_ptr<detail::flush_backend_cmd>( cmd.flush_cmd = std::unique_ptr<detail::flush_backend_cmd>(
new detail::flush_backend_cmd{completion_flag, std::move(sinks)}); new detail::flush_backend_cmd{completion_flag, std::move(sinks)});

@ -32,6 +32,8 @@ public:
return true; return true;
} }
fmt::dynamic_format_arg_store<fmt::printf_context>* alloc_arg_store() override { return &store; }
bool is_running() const override { return true; } bool is_running() const override { return true; }
void reset() { count = 0; } void reset() { count = 0; }
@ -39,13 +41,13 @@ public:
unsigned push_invocation_count() const { return count; } unsigned push_invocation_count() const { return count; }
private: private:
unsigned count = 0; unsigned count = 0;
fmt::dynamic_format_arg_store<fmt::printf_context> store;
}; };
} // namespace } // namespace
static bool static bool when_tracing_with_duration_event_then_two_events_are_generated(backend_spy& spy)
when_tracing_with_duration_event_then_two_events_are_generated(backend_spy& spy)
{ {
trace_duration_begin("a", "b"); trace_duration_begin("a", "b");
ASSERT_EQ(spy.push_invocation_count(), 1); ASSERT_EQ(spy.push_invocation_count(), 1);
@ -56,8 +58,7 @@ when_tracing_with_duration_event_then_two_events_are_generated(backend_spy& spy)
return true; return true;
} }
static bool static bool when_tracing_with_complete_event_then_one_event_is_generated(backend_spy& spy)
when_tracing_with_complete_event_then_one_event_is_generated(backend_spy& spy)
{ {
{ {
trace_complete_event("a", "b"); trace_complete_event("a", "b");
@ -70,17 +71,15 @@ when_tracing_with_complete_event_then_one_event_is_generated(backend_spy& spy)
int main() int main()
{ {
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
backend_spy backend; backend_spy backend;
log_channel c("test", s, backend); log_channel c("test", s, backend);
// Inject our spy into the framework. // Inject our spy into the framework.
event_trace_init(c); event_trace_init(c);
TEST_FUNCTION(when_tracing_with_duration_event_then_two_events_are_generated, TEST_FUNCTION(when_tracing_with_duration_event_then_two_events_are_generated, backend);
backend);
backend.reset(); backend.reset();
TEST_FUNCTION(when_tracing_with_complete_event_then_one_event_is_generated, TEST_FUNCTION(when_tracing_with_complete_event_then_one_event_is_generated, backend);
backend);
return 0; return 0;
} }

@ -18,23 +18,25 @@
using namespace srslog; using namespace srslog;
/// Helper to build a log entry. /// Helper to build a log entry.
static detail::log_entry_metadata build_log_entry_metadata() static detail::log_entry_metadata build_log_entry_metadata(fmt::dynamic_format_arg_store<fmt::printf_context>* store)
{ {
// Create a time point 50000us from epoch. // Create a time point 50000us from epoch.
using tp_ty = std::chrono::time_point<std::chrono::high_resolution_clock>; using tp_ty = std::chrono::time_point<std::chrono::high_resolution_clock>;
tp_ty tp(std::chrono::microseconds(50000)); tp_ty tp(std::chrono::microseconds(50000));
fmt::dynamic_format_arg_store<fmt::printf_context> store; if (store) {
store.push_back(88); store->push_back(88);
}
return {tp, {10, true}, "Text %d", std::move(store), "ABC", 'Z', small_str_buffer()}; return {tp, {10, true}, "Text %d", store, "ABC", 'Z', small_str_buffer()};
} }
static bool when_fully_filled_log_entry_then_everything_is_formatted() static bool when_fully_filled_log_entry_then_everything_is_formatted()
{ {
fmt::memory_buffer buffer; fmt::dynamic_format_arg_store<fmt::printf_context> store;
json_formatter{}.format(build_log_entry_metadata(), buffer); fmt::memory_buffer buffer;
std::string result = fmt::to_string(buffer); json_formatter{}.format(build_log_entry_metadata(&store), buffer);
std::string result = fmt::to_string(buffer);
std::string expected = "{\n" std::string expected = "{\n"
" \"log_entry\": \"Text 88\"\n" " \"log_entry\": \"Text 88\"\n"
"}\n"; "}\n";
@ -44,21 +46,20 @@ static bool when_fully_filled_log_entry_then_everything_is_formatted()
return true; return true;
} }
static bool static bool when_fully_filled_log_entry_with_hex_dump_then_everything_is_formatted()
when_fully_filled_log_entry_with_hex_dump_then_everything_is_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
auto entry = build_log_entry_metadata(&store);
entry.hex_dump.resize(12); entry.hex_dump.resize(12);
std::iota(entry.hex_dump.begin(), entry.hex_dump.end(), 0); std::iota(entry.hex_dump.begin(), entry.hex_dump.end(), 0);
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
json_formatter{}.format(std::move(entry), buffer); json_formatter{}.format(std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = std::string expected = "{\n"
"{\n" " \"log_entry\": \"Text 88\",\n"
" \"log_entry\": \"Text 88\",\n" " \"hex_dump\": \"00 01 02 03 04 05 06 07 08 09 0a 0b\"\n"
" \"hex_dump\": \"00 01 02 03 04 05 06 07 08 09 0a 0b\"\n" "}\n";
"}\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -78,10 +79,9 @@ DECLARE_METRIC_SET("Network", myset2, thr_t, ip_addr_t);
using basic_ctx_t = srslog::build_context_type<myset1, myset2>; using basic_ctx_t = srslog::build_context_type<myset1, myset2>;
} // namespace } // namespace
static bool static bool when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted()
when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted()
{ {
auto entry = build_log_entry_metadata(); auto entry = build_log_entry_metadata(nullptr);
entry.fmtstring = nullptr; entry.fmtstring = nullptr;
basic_ctx_t ctx("UL Context"); basic_ctx_t ctx("UL Context");
@ -93,7 +93,7 @@ when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted()
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
json_formatter{}.format_ctx(ctx, std::move(entry), buffer); json_formatter{}.format_ctx(ctx, std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "{\n" std::string expected = "{\n"
" \"RF\": {\n" " \"RF\": {\n"
" \"SNR\": -55.1,\n" " \"SNR\": -55.1,\n"
@ -111,11 +111,11 @@ when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted()
return true; return true;
} }
static bool static bool when_log_entry_with_message_and_basic_context_is_passed_then_context_is_formatted()
when_log_entry_with_message_and_basic_context_is_passed_then_context_is_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
basic_ctx_t ctx("UL Context"); auto entry = build_log_entry_metadata(&store);
basic_ctx_t ctx("UL Context");
ctx.get<myset1>().write<snr_t>(-55.1); ctx.get<myset1>().write<snr_t>(-55.1);
ctx.get<myset1>().write<pwr_t>(-10); ctx.get<myset1>().write<pwr_t>(-10);
@ -125,7 +125,7 @@ when_log_entry_with_message_and_basic_context_is_passed_then_context_is_formatte
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
json_formatter{}.format_ctx(ctx, std::move(entry), buffer); json_formatter{}.format_ctx(ctx, std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "{\n" std::string expected = "{\n"
" \"log_entry\": \"Text 88\",\n" " \"log_entry\": \"Text 88\",\n"
" \"RF\": {\n" " \"RF\": {\n"
@ -157,23 +157,18 @@ DECLARE_METRIC_SET("ue_container", ue_set, ue_rnti_t, dl_cqi_t, bearer_list_t);
DECLARE_METRIC("type", entry_type_t, std::string, ""); DECLARE_METRIC("type", entry_type_t, std::string, "");
DECLARE_METRIC("sector_id", sector_id_t, unsigned, ""); DECLARE_METRIC("sector_id", sector_id_t, unsigned, "");
DECLARE_METRIC_LIST("ue_list", ue_list_t, std::vector<ue_set>); DECLARE_METRIC_LIST("ue_list", ue_list_t, std::vector<ue_set>);
DECLARE_METRIC_SET("sector_metrics", DECLARE_METRIC_SET("sector_metrics", sector_set, entry_type_t, sector_id_t, ue_list_t);
sector_set,
entry_type_t,
sector_id_t,
ue_list_t);
DECLARE_METRIC_LIST("sector_list", sector_list_t, std::vector<sector_set>); DECLARE_METRIC_LIST("sector_list", sector_list_t, std::vector<sector_set>);
using complex_ctx_t = srslog::build_context_type<sector_list_t>; using complex_ctx_t = srslog::build_context_type<sector_list_t>;
} // namespace } // namespace
static bool static bool when_log_entry_with_only_complex_context_is_passed_then_context_is_formatted()
when_log_entry_with_only_complex_context_is_passed_then_context_is_formatted()
{ {
complex_ctx_t ctx("UL Context"); complex_ctx_t ctx("UL Context");
auto entry = build_log_entry_metadata(); auto entry = build_log_entry_metadata(nullptr);
entry.fmtstring = nullptr; entry.fmtstring = nullptr;
ctx.get<sector_list_t>().emplace_back(); ctx.get<sector_list_t>().emplace_back();
ctx.at<sector_list_t>(0).get<ue_list_t>().emplace_back(); ctx.at<sector_list_t>(0).get<ue_list_t>().emplace_back();
@ -187,7 +182,7 @@ when_log_entry_with_only_complex_context_is_passed_then_context_is_formatted()
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
json_formatter{}.format_ctx(ctx, std::move(entry), buffer); json_formatter{}.format_ctx(ctx, std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "{\n" std::string expected = "{\n"
" \"sector_list\": [\n" " \"sector_list\": [\n"
" {\n" " {\n"
@ -252,19 +247,18 @@ DECLARE_METRIC_SET("metric_list_set", metric_list_set, list_metric2);
DECLARE_METRIC_LIST("metrics_list", metrics_list, std::vector<metric_list_set>); DECLARE_METRIC_LIST("metrics_list", metrics_list, std::vector<metric_list_set>);
DECLARE_METRIC("list_metric3", list_metric3, unsigned, ""); DECLARE_METRIC("list_metric3", list_metric3, unsigned, "");
DECLARE_METRIC("list_metric4", list_metric4, unsigned, ""); DECLARE_METRIC("list_metric4", list_metric4, unsigned, "");
using list_ctx_t = using list_ctx_t = srslog::build_context_type<list_metric3, list_metric4, metrics_list>;
srslog::build_context_type<list_metric3, list_metric4, metrics_list>;
}; // namespace }; // namespace
static bool when_context_with_empty_list_is_passed_then_list_object_is_empty() static bool when_context_with_empty_list_is_passed_then_list_object_is_empty()
{ {
list_ctx_t ctx("UL Context"); list_ctx_t ctx("UL Context");
auto entry = build_log_entry_metadata(); auto entry = build_log_entry_metadata(nullptr);
entry.fmtstring = nullptr; entry.fmtstring = nullptr;
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
json_formatter{}.format_ctx(ctx, std::move(entry), buffer); json_formatter{}.format_ctx(ctx, std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "{\n" std::string expected = "{\n"
" \"list_metric3\": 0,\n" " \"list_metric3\": 0,\n"
" \"list_metric4\": 0,\n" " \"list_metric4\": 0,\n"
@ -280,16 +274,11 @@ static bool when_context_with_empty_list_is_passed_then_list_object_is_empty()
int main() int main()
{ {
TEST_FUNCTION(when_fully_filled_log_entry_then_everything_is_formatted); TEST_FUNCTION(when_fully_filled_log_entry_then_everything_is_formatted);
TEST_FUNCTION( TEST_FUNCTION(when_fully_filled_log_entry_with_hex_dump_then_everything_is_formatted);
when_fully_filled_log_entry_with_hex_dump_then_everything_is_formatted); TEST_FUNCTION(when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted);
TEST_FUNCTION( TEST_FUNCTION(when_log_entry_with_message_and_basic_context_is_passed_then_context_is_formatted);
when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted); TEST_FUNCTION(when_log_entry_with_only_complex_context_is_passed_then_context_is_formatted);
TEST_FUNCTION( TEST_FUNCTION(when_context_with_empty_list_is_passed_then_list_object_is_empty);
when_log_entry_with_message_and_basic_context_is_passed_then_context_is_formatted);
TEST_FUNCTION(
when_log_entry_with_only_complex_context_is_passed_then_context_is_formatted);
TEST_FUNCTION(
when_context_with_empty_list_is_passed_then_list_object_is_empty);
return 0; return 0;
} }

@ -46,9 +46,7 @@ namespace {
class sink_spy : public sink class sink_spy : public sink
{ {
public: public:
sink_spy() : sink_spy() : sink(std::unique_ptr<log_formatter>(new test_dummies::log_formatter_dummy)) {}
sink(std::unique_ptr<log_formatter>(new test_dummies::log_formatter_dummy))
{}
detail::error_string write(detail::memory_buffer buffer) override detail::error_string write(detail::memory_buffer buffer) override
{ {
@ -64,33 +62,33 @@ public:
const std::string& received_buffer() const { return str; } const std::string& received_buffer() const { return str; }
private: private:
unsigned count = 0; unsigned count = 0;
std::string str; std::string str;
}; };
} // namespace } // namespace
/// Builds a basic log entry. /// Builds a basic log entry.
static detail::log_entry build_log_entry(sink* s) static detail::log_entry build_log_entry(sink* s, fmt::dynamic_format_arg_store<fmt::printf_context>* store)
{ {
using tp_ty = std::chrono::time_point<std::chrono::high_resolution_clock>; using tp_ty = std::chrono::time_point<std::chrono::high_resolution_clock>;
tp_ty tp; tp_ty tp;
fmt::dynamic_format_arg_store<fmt::printf_context> store; if (store) {
store.push_back(88); store->push_back(88);
}
return { return {s,
s, [](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {},
[](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {}, {tp, {0, false}, "Text %d", store, "", '\0', small_str_buffer()}};
{tp, {0, false}, "Text %d", std::move(store), "", '\0', small_str_buffer()}};
} }
static bool when_backend_is_not_started_then_pushed_log_entries_are_ignored() static bool when_backend_is_not_started_then_pushed_log_entries_are_ignored()
{ {
sink_spy spy; sink_spy spy;
log_backend_impl backend; log_backend_impl backend;
backend.push(build_log_entry(&spy)); backend.push(build_log_entry(&spy, backend.alloc_arg_store()));
ASSERT_EQ(spy.write_invocation_count(), 0); ASSERT_EQ(spy.write_invocation_count(), 0);
@ -104,7 +102,7 @@ static bool when_backend_is_started_then_pushed_log_entries_are_sent_to_sink()
log_backend_impl backend; log_backend_impl backend;
backend.start(); backend.start();
backend.push(build_log_entry(&spy)); backend.push(build_log_entry(&spy, backend.alloc_arg_store()));
// Stop the backend to ensure the entry has been processed. // Stop the backend to ensure the entry has been processed.
backend.stop(); backend.stop();
@ -121,10 +119,9 @@ static bool when_backend_is_started_then_backend_invokes_format_func()
log_backend_impl backend; log_backend_impl backend;
backend.start(); backend.start();
auto entry = build_log_entry(&s); auto entry = build_log_entry(&s, backend.alloc_arg_store());
unsigned counter = 0; unsigned counter = 0;
entry.format_func = [&counter](detail::log_entry_metadata&& metadata, entry.format_func = [&counter](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) { ++counter; };
fmt::memory_buffer& buffer) { ++counter; };
backend.push(std::move(entry)); backend.push(std::move(entry));
// Stop the backend to ensure the entry has been processed. // Stop the backend to ensure the entry has been processed.
@ -144,14 +141,10 @@ class sink_error_stub : public sink
{ {
public: public:
explicit sink_error_stub(std::string err) : explicit sink_error_stub(std::string err) :
sink(std::unique_ptr<log_formatter>(new test_dummies::log_formatter_dummy)), sink(std::unique_ptr<log_formatter>(new test_dummies::log_formatter_dummy)), err(std::move(err))
err(std::move(err))
{} {}
detail::error_string write(detail::memory_buffer buffer) override detail::error_string write(detail::memory_buffer buffer) override { return err; }
{
return err;
}
detail::error_string flush() override { return err; } detail::error_string flush() override { return err; }
@ -163,11 +156,11 @@ private:
static bool when_sink_write_fails_then_error_handler_is_invoked() static bool when_sink_write_fails_then_error_handler_is_invoked()
{ {
std::string error_str("error"); std::string error_str("error");
sink_error_stub s(error_str); sink_error_stub s(error_str);
bool valid_err = false; bool valid_err = false;
unsigned count = 0; unsigned count = 0;
// valid_err checks that the input error matches the expected string. // valid_err checks that the input error matches the expected string.
// The count variable counts the number of calls. // The count variable counts the number of calls.
auto handler = [&count, &valid_err, error_str](const std::string& error) { auto handler = [&count, &valid_err, error_str](const std::string& error) {
@ -179,7 +172,7 @@ static bool when_sink_write_fails_then_error_handler_is_invoked()
backend.set_error_handler(handler); backend.set_error_handler(handler);
backend.start(); backend.start();
backend.push(build_log_entry(&s)); backend.push(build_log_entry(&s, backend.alloc_arg_store()));
// Stop the backend to ensure the entry has been processed. // Stop the backend to ensure the entry has been processed.
backend.stop(); backend.stop();
@ -204,7 +197,7 @@ static bool when_handler_is_set_after_start_then_handler_is_not_used()
backend.start(); backend.start();
backend.set_error_handler(handler); backend.set_error_handler(handler);
backend.push(build_log_entry(&s)); backend.push(build_log_entry(&s, backend.alloc_arg_store()));
// Stop the backend to ensure the entry has been processed. // Stop the backend to ensure the entry has been processed.
backend.stop(); backend.stop();
@ -223,7 +216,7 @@ static bool when_empty_handler_is_used_then_backend_does_not_crash()
backend.set_error_handler({}); backend.set_error_handler({});
backend.start(); backend.start();
backend.push(build_log_entry(&s)); backend.push(build_log_entry(&s, backend.alloc_arg_store()));
// Stop the backend to ensure the entry has been processed. // Stop the backend to ensure the entry has been processed.
backend.stop(); backend.stop();
@ -234,12 +227,9 @@ static bool when_empty_handler_is_used_then_backend_does_not_crash()
int main() int main()
{ {
TEST_FUNCTION(when_backend_is_started_then_is_started_returns_true); TEST_FUNCTION(when_backend_is_started_then_is_started_returns_true);
TEST_FUNCTION( TEST_FUNCTION(when_backend_is_started_and_stopped_then_is_started_returns_false);
when_backend_is_started_and_stopped_then_is_started_returns_false); TEST_FUNCTION(when_backend_is_not_started_then_pushed_log_entries_are_ignored);
TEST_FUNCTION( TEST_FUNCTION(when_backend_is_started_then_pushed_log_entries_are_sent_to_sink);
when_backend_is_not_started_then_pushed_log_entries_are_ignored);
TEST_FUNCTION(
when_backend_is_started_then_pushed_log_entries_are_sent_to_sink);
TEST_FUNCTION(when_backend_is_started_then_backend_invokes_format_func); TEST_FUNCTION(when_backend_is_started_then_backend_invokes_format_func);
TEST_FUNCTION(when_sink_write_fails_then_error_handler_is_invoked); TEST_FUNCTION(when_sink_write_fails_then_error_handler_is_invoked);
TEST_FUNCTION(when_handler_is_set_after_start_then_handler_is_not_used); TEST_FUNCTION(when_handler_is_set_after_start_then_handler_is_not_used);

@ -19,8 +19,8 @@ using namespace srslog;
static bool when_log_channel_is_created_then_id_matches_expected_value() static bool when_log_channel_is_created_then_id_matches_expected_value()
{ {
test_dummies::backend_dummy backend; test_dummies::backend_dummy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
log_channel log("id", s, backend); log_channel log("id", s, backend);
ASSERT_EQ(log.id(), "id"); ASSERT_EQ(log.id(), "id");
@ -30,8 +30,8 @@ static bool when_log_channel_is_created_then_id_matches_expected_value()
static bool when_log_channel_is_disabled_then_enabled_returns_false() static bool when_log_channel_is_disabled_then_enabled_returns_false()
{ {
test_dummies::backend_dummy backend; test_dummies::backend_dummy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
log_channel log("id", s, backend); log_channel log("id", s, backend);
log.set_enabled(false); log.set_enabled(false);
@ -43,8 +43,8 @@ static bool when_log_channel_is_disabled_then_enabled_returns_false()
static bool when_log_channel_is_enabled_then_enabled_returns_true() static bool when_log_channel_is_enabled_then_enabled_returns_true()
{ {
test_dummies::backend_dummy backend; test_dummies::backend_dummy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
log_channel log("id", s, backend); log_channel log("id", s, backend);
log.set_enabled(true); log.set_enabled(true);
@ -71,23 +71,25 @@ public:
bool is_running() const override { return true; } bool is_running() const override { return true; }
fmt::dynamic_format_arg_store<fmt::printf_context>* alloc_arg_store() override { return &store; }
unsigned push_invocation_count() const { return count; } unsigned push_invocation_count() const { return count; }
const detail::log_entry& last_entry() const { return e; } const detail::log_entry& last_entry() const { return e; }
private: private:
unsigned count = 0; unsigned count = 0;
detail::log_entry e; detail::log_entry e;
fmt::dynamic_format_arg_store<fmt::printf_context> store;
}; };
} // namespace } // namespace
static bool static bool when_logging_in_log_channel_then_log_entry_is_pushed_into_the_backend()
when_logging_in_log_channel_then_log_entry_is_pushed_into_the_backend()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
log_channel log("id", s, backend); log_channel log("id", s, backend);
log("test", 42, "Hello"); log("test", 42, "Hello");
@ -98,9 +100,9 @@ when_logging_in_log_channel_then_log_entry_is_pushed_into_the_backend()
static bool when_logging_in_disabled_log_channel_then_log_entry_is_ignored() static bool when_logging_in_disabled_log_channel_then_log_entry_is_ignored()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
log_channel log("id", s, backend); log_channel log("id", s, backend);
log.set_enabled(false); log.set_enabled(false);
log("test", 42, "Hello"); log("test", 42, "Hello");
@ -112,11 +114,11 @@ static bool when_logging_in_disabled_log_channel_then_log_entry_is_ignored()
static bool when_logging_then_filled_in_log_entry_is_pushed_into_the_backend() static bool when_logging_then_filled_in_log_entry_is_pushed_into_the_backend()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
std::string name = "name"; std::string name = "name";
char tag = 'A'; char tag = 'A';
log_channel log("id", s, backend, {name, tag, true}); log_channel log("id", s, backend, {name, tag, true});
@ -141,14 +143,13 @@ static bool when_logging_then_filled_in_log_entry_is_pushed_into_the_backend()
return true; return true;
} }
static bool static bool when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend()
when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
std::string name = "name"; std::string name = "name";
char tag = 'A'; char tag = 'A';
log_channel log("id", s, backend, {name, tag, true}); log_channel log("id", s, backend, {name, tag, true});
@ -171,18 +172,14 @@ when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend()
ASSERT_EQ(entry.metadata.log_name, name); ASSERT_EQ(entry.metadata.log_name, name);
ASSERT_EQ(entry.metadata.log_tag, tag); ASSERT_EQ(entry.metadata.log_tag, tag);
ASSERT_EQ(entry.metadata.hex_dump.size(), 4); ASSERT_EQ(entry.metadata.hex_dump.size(), 4);
ASSERT_EQ(std::equal(entry.metadata.hex_dump.begin(), ASSERT_EQ(std::equal(entry.metadata.hex_dump.begin(), entry.metadata.hex_dump.end(), std::begin(hex)), true);
entry.metadata.hex_dump.end(),
std::begin(hex)),
true);
return true; return true;
} }
static bool static bool when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used()
when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
std::string name = "name"; std::string name = "name";
@ -197,10 +194,7 @@ when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used()
const detail::log_entry& entry = backend.last_entry(); const detail::log_entry& entry = backend.last_entry();
ASSERT_EQ(entry.metadata.hex_dump.size(), 3); ASSERT_EQ(entry.metadata.hex_dump.size(), 3);
ASSERT_EQ(std::equal(entry.metadata.hex_dump.begin(), ASSERT_EQ(std::equal(entry.metadata.hex_dump.begin(), entry.metadata.hex_dump.end(), std::begin(hex)), true);
entry.metadata.hex_dump.end(),
std::begin(hex)),
true);
return true; return true;
} }
@ -213,14 +207,13 @@ using my_ctx = srslog::build_context_type<my_set>;
} // namespace } // namespace
static bool static bool when_logging_with_context_then_filled_in_log_entry_is_pushed_into_the_backend()
when_logging_with_context_then_filled_in_log_entry_is_pushed_into_the_backend()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
std::string name = "name"; std::string name = "name";
char tag = 'A'; char tag = 'A';
log_channel log("id", s, backend, {name, tag, true}); log_channel log("id", s, backend, {name, tag, true});
@ -245,14 +238,13 @@ when_logging_with_context_then_filled_in_log_entry_is_pushed_into_the_backend()
return true; return true;
} }
static bool static bool when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_the_backend()
when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_the_backend()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
std::string name = "name"; std::string name = "name";
char tag = 'A'; char tag = 'A';
log_channel log("id", s, backend, {name, tag, true}); log_channel log("id", s, backend, {name, tag, true});
@ -278,10 +270,9 @@ when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_th
return true; return true;
} }
static bool static bool when_logging_with_small_string_then_filled_in_log_entry_is_pushed_into_the_backend()
when_logging_with_small_string_then_filled_in_log_entry_is_pushed_into_the_backend()
{ {
backend_spy backend; backend_spy backend;
test_dummies::sink_dummy s; test_dummies::sink_dummy s;
log_channel log("id", s, backend); log_channel log("id", s, backend);
@ -308,21 +299,14 @@ int main()
TEST_FUNCTION(when_log_channel_is_created_then_id_matches_expected_value); TEST_FUNCTION(when_log_channel_is_created_then_id_matches_expected_value);
TEST_FUNCTION(when_log_channel_is_disabled_then_enabled_returns_false); TEST_FUNCTION(when_log_channel_is_disabled_then_enabled_returns_false);
TEST_FUNCTION(when_log_channel_is_enabled_then_enabled_returns_true); TEST_FUNCTION(when_log_channel_is_enabled_then_enabled_returns_true);
TEST_FUNCTION( TEST_FUNCTION(when_logging_in_log_channel_then_log_entry_is_pushed_into_the_backend);
when_logging_in_log_channel_then_log_entry_is_pushed_into_the_backend);
TEST_FUNCTION(when_logging_in_disabled_log_channel_then_log_entry_is_ignored); TEST_FUNCTION(when_logging_in_disabled_log_channel_then_log_entry_is_ignored);
TEST_FUNCTION( TEST_FUNCTION(when_logging_then_filled_in_log_entry_is_pushed_into_the_backend);
when_logging_then_filled_in_log_entry_is_pushed_into_the_backend); TEST_FUNCTION(when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend);
TEST_FUNCTION( TEST_FUNCTION(when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used);
when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend); TEST_FUNCTION(when_logging_with_context_then_filled_in_log_entry_is_pushed_into_the_backend);
TEST_FUNCTION( TEST_FUNCTION(when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_the_backend);
when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used); TEST_FUNCTION(when_logging_with_small_string_then_filled_in_log_entry_is_pushed_into_the_backend);
TEST_FUNCTION(
when_logging_with_context_then_filled_in_log_entry_is_pushed_into_the_backend);
TEST_FUNCTION(
when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_the_backend);
TEST_FUNCTION(
when_logging_with_small_string_then_filled_in_log_entry_is_pushed_into_the_backend);
return 0; return 0;
} }

@ -22,45 +22,32 @@ namespace test_dummies {
class log_formatter_dummy : public srslog::log_formatter class log_formatter_dummy : public srslog::log_formatter
{ {
public: public:
void format(srslog::detail::log_entry_metadata&& metadata, void format(srslog::detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) override {}
fmt::memory_buffer& buffer) override
{}
std::unique_ptr<log_formatter> clone() const override { return nullptr; } std::unique_ptr<log_formatter> clone() const override { return nullptr; }
private: private:
void format_context_begin(const srslog::detail::log_entry_metadata& md, void format_context_begin(const srslog::detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
unsigned size, unsigned size,
fmt::memory_buffer& buffer) override fmt::memory_buffer& buffer) override
{} {}
void format_context_end(const srslog::detail::log_entry_metadata& md, void format_context_end(const srslog::detail::log_entry_metadata& md,
const std::string& ctx_name, fmt::string_view ctx_name,
fmt::memory_buffer& buffer) override fmt::memory_buffer& buffer) override
{}
void format_metric_set_begin(const std::string& set_name,
unsigned size,
unsigned level,
fmt::memory_buffer& buffer) override
{}
void format_metric_set_end(const std::string& set_name,
unsigned level,
fmt::memory_buffer& buffer) override
{} {}
void format_list_begin(const std::string& list_name, void
unsigned size, format_metric_set_begin(fmt::string_view set_name, unsigned size, unsigned level, fmt::memory_buffer& buffer) override
unsigned level,
fmt::memory_buffer& buffer) override
{} {}
void format_list_end(const std::string& list_name, void format_metric_set_end(fmt::string_view set_name, unsigned level, fmt::memory_buffer& buffer) override {}
unsigned level, void format_list_begin(fmt::string_view list_name, unsigned size, unsigned level, fmt::memory_buffer& buffer) override
fmt::memory_buffer& buffer) override
{} {}
void format_metric(const std::string& metric_name, void format_list_end(fmt::string_view list_name, unsigned level, fmt::memory_buffer& buffer) override {}
const std::string& metric_value, void format_metric(fmt::string_view metric_name,
const std::string& metric_units, fmt::string_view metric_value,
fmt::string_view metric_units,
srslog::metric_kind kind, srslog::metric_kind kind,
unsigned level, unsigned level,
fmt::memory_buffer& buffer) override fmt::memory_buffer& buffer) override
{} {}
}; };
@ -69,15 +56,9 @@ private:
class sink_dummy : public srslog::sink class sink_dummy : public srslog::sink
{ {
public: public:
sink_dummy() : sink_dummy() : sink(std::unique_ptr<srslog::log_formatter>(new log_formatter_dummy)) {}
sink(std::unique_ptr<srslog::log_formatter>(new log_formatter_dummy))
{}
srslog::detail::error_string srslog::detail::error_string write(srslog::detail::memory_buffer buffer) override { return {}; }
write(srslog::detail::memory_buffer buffer) override
{
return {};
}
srslog::detail::error_string flush() override { return {}; } srslog::detail::error_string flush() override { return {}; }
}; };
@ -91,6 +72,8 @@ public:
bool push(srslog::detail::log_entry&& entry) override { return true; } bool push(srslog::detail::log_entry&& entry) override { return true; }
bool is_running() const override { return true; } bool is_running() const override { return true; }
fmt::dynamic_format_arg_store<fmt::printf_context>* alloc_arg_store() override { return nullptr; }
}; };
} // namespace test_dummies } // namespace test_dummies

@ -18,23 +18,25 @@
using namespace srslog; using namespace srslog;
/// Helper to build a log entry. /// Helper to build a log entry.
static detail::log_entry_metadata build_log_entry_metadata() static detail::log_entry_metadata build_log_entry_metadata(fmt::dynamic_format_arg_store<fmt::printf_context>* store)
{ {
// Create a time point 50000us from epoch. // Create a time point 50000us from epoch.
using tp_ty = std::chrono::time_point<std::chrono::high_resolution_clock>; using tp_ty = std::chrono::time_point<std::chrono::high_resolution_clock>;
tp_ty tp(std::chrono::microseconds(50000)); tp_ty tp(std::chrono::microseconds(50000));
fmt::dynamic_format_arg_store<fmt::printf_context> store; if (store) {
store.push_back(88); store->push_back(88);
}
return {tp, {10, true}, "Text %d", std::move(store), "ABC", 'Z', small_str_buffer()}; return {tp, {10, true}, "Text %d", store, "ABC", 'Z', small_str_buffer()};
} }
static bool when_fully_filled_log_entry_then_everything_is_formatted() static bool when_fully_filled_log_entry_then_everything_is_formatted()
{ {
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format(build_log_entry_metadata(), buffer); fmt::dynamic_format_arg_store<fmt::printf_context> store;
std::string result = fmt::to_string(buffer); text_formatter{}.format(build_log_entry_metadata(&store), buffer);
std::string result = fmt::to_string(buffer);
std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] Text 88\n"; std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] Text 88\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -44,12 +46,13 @@ static bool when_fully_filled_log_entry_then_everything_is_formatted()
static bool when_log_entry_without_name_is_passed_then_name_is_not_formatted() static bool when_log_entry_without_name_is_passed_then_name_is_not_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
entry.log_name = ""; auto entry = build_log_entry_metadata(&store);
entry.log_name = "";
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format(std::move(entry), buffer); text_formatter{}.format(std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "00:00:00.050000 [Z] [ 10] Text 88\n"; std::string expected = "00:00:00.050000 [Z] [ 10] Text 88\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -59,12 +62,13 @@ static bool when_log_entry_without_name_is_passed_then_name_is_not_formatted()
static bool when_log_entry_without_tag_is_passed_then_tag_is_not_formatted() static bool when_log_entry_without_tag_is_passed_then_tag_is_not_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
entry.log_tag = '\0'; auto entry = build_log_entry_metadata(&store);
entry.log_tag = '\0';
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format(std::move(entry), buffer); text_formatter{}.format(std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "00:00:00.050000 [ABC ] [ 10] Text 88\n"; std::string expected = "00:00:00.050000 [ABC ] [ 10] Text 88\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -72,15 +76,15 @@ static bool when_log_entry_without_tag_is_passed_then_tag_is_not_formatted()
return true; return true;
} }
static bool static bool when_log_entry_without_context_is_passed_then_context_is_not_formatted()
when_log_entry_without_context_is_passed_then_context_is_not_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
entry.context.enabled = false; auto entry = build_log_entry_metadata(&store);
entry.context.enabled = false;
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format(std::move(entry), buffer); text_formatter{}.format(std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "00:00:00.050000 [ABC ] [Z] Text 88\n"; std::string expected = "00:00:00.050000 [ABC ] [Z] Text 88\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -90,17 +94,17 @@ when_log_entry_without_context_is_passed_then_context_is_not_formatted()
static bool when_log_entry_with_hex_dump_is_passed_then_hex_dump_is_formatted() static bool when_log_entry_with_hex_dump_is_passed_then_hex_dump_is_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
auto entry = build_log_entry_metadata(&store);
entry.hex_dump.resize(20); entry.hex_dump.resize(20);
std::iota(entry.hex_dump.begin(), entry.hex_dump.end(), 0); std::iota(entry.hex_dump.begin(), entry.hex_dump.end(), 0);
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format(std::move(entry), buffer); text_formatter{}.format(std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] Text 88\n"
"00:00:00.050000 [ABC ] [Z] [ 10] Text 88\n" " 0000: 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f\n"
" 0000: 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f\n" " 0010: 10 11 12 13\n";
" 0010: 10 11 12 13\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -120,11 +124,7 @@ DECLARE_METRIC_SET("ue_container", ue_set, thr_t, ip_addr_t, antenna_list_t);
DECLARE_METRIC("type", entry_type_t, std::string, ""); DECLARE_METRIC("type", entry_type_t, std::string, "");
DECLARE_METRIC("sector_id", sector_id_t, unsigned, ""); DECLARE_METRIC("sector_id", sector_id_t, unsigned, "");
DECLARE_METRIC_LIST("ue_list", ue_list_t, std::vector<ue_set>); DECLARE_METRIC_LIST("ue_list", ue_list_t, std::vector<ue_set>);
DECLARE_METRIC_SET("sector_metrics", DECLARE_METRIC_SET("sector_metrics", sector_set, entry_type_t, sector_id_t, ue_list_t);
sector_set,
entry_type_t,
sector_id_t,
ue_list_t);
DECLARE_METRIC_LIST("sector_list", sector_list_t, std::vector<sector_set>); DECLARE_METRIC_LIST("sector_list", sector_list_t, std::vector<sector_set>);
@ -149,54 +149,33 @@ static complex_ctx_t build_complex_context()
ctx.at<sector_list_t>(0).at<ue_list_t>(1).write<thr_t>(10.2); ctx.at<sector_list_t>(0).at<ue_list_t>(1).write<thr_t>(10.2);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).write<ip_addr_t>("10.20.30.41"); ctx.at<sector_list_t>(0).at<ue_list_t>(1).write<ip_addr_t>("10.20.30.41");
ctx.at<sector_list_t>(0) ctx.at<sector_list_t>(0).at<ue_list_t>(0).get<antenna_list_t>().emplace_back();
.at<ue_list_t>(0) ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(0).write<snr_t>(5.1);
.get<antenna_list_t>() ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(0).write<pwr_t>(-11.5);
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(0).write<snr_t>( ctx.at<sector_list_t>(0).at<ue_list_t>(0).get<antenna_list_t>().emplace_back();
5.1); ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(1).write<snr_t>(10.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(0).write<pwr_t>( ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(1).write<pwr_t>(-20.5);
-11.5);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).get<antenna_list_t>().emplace_back();
ctx.at<sector_list_t>(0) ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(0).write<snr_t>(20.1);
.at<ue_list_t>(0) ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(0).write<pwr_t>(-30.5);
.get<antenna_list_t>() ctx.at<sector_list_t>(0).at<ue_list_t>(1).get<antenna_list_t>().emplace_back();
.emplace_back(); ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(1).write<snr_t>(30.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(1).write<snr_t>( ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(1).write<pwr_t>(-40.5);
10.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(1).write<pwr_t>(
-20.5);
ctx.at<sector_list_t>(0)
.at<ue_list_t>(1)
.get<antenna_list_t>()
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(0).write<snr_t>(
20.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(0).write<pwr_t>(
-30.5);
ctx.at<sector_list_t>(0)
.at<ue_list_t>(1)
.get<antenna_list_t>()
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(1).write<snr_t>(
30.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(1).write<pwr_t>(
-40.5);
return ctx; return ctx;
} }
static bool static bool when_log_entry_with_only_context_is_passed_then_context_is_formatted()
when_log_entry_with_only_context_is_passed_then_context_is_formatted()
{ {
auto ctx = build_complex_context(); auto ctx = build_complex_context();
auto entry = build_log_entry_metadata(); auto entry = build_log_entry_metadata(nullptr);
entry.fmtstring = nullptr; entry.fmtstring = nullptr;
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format_ctx(ctx, std::move(entry), buffer); text_formatter{}.format_ctx(ctx, std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] Context dump for " std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] Context dump for "
"\"Complex Context\"\n" "\"Complex Context\"\n"
" > List: sector_list\n" " > List: sector_list\n"
@ -230,22 +209,21 @@ when_log_entry_with_only_context_is_passed_then_context_is_formatted()
return true; return true;
} }
static bool static bool when_log_entry_with_context_and_message_is_passed_then_context_is_formatted()
when_log_entry_with_context_and_message_is_passed_then_context_is_formatted()
{ {
auto entry = build_log_entry_metadata(); fmt::dynamic_format_arg_store<fmt::printf_context> store;
auto ctx = build_complex_context(); auto entry = build_log_entry_metadata(&store);
auto ctx = build_complex_context();
fmt::memory_buffer buffer; fmt::memory_buffer buffer;
text_formatter{}.format_ctx(ctx, std::move(entry), buffer); text_formatter{}.format_ctx(ctx, std::move(entry), buffer);
std::string result = fmt::to_string(buffer); std::string result = fmt::to_string(buffer);
std::string expected = std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] [[sector_metrics_type: event, "
"00:00:00.050000 [ABC ] [Z] [ 10] [[sector_metrics_type: event, " "sector_metrics_sector_id: 1, [ue_container_Throughput: 1.2 MB/s, "
"sector_metrics_sector_id: 1, [ue_container_Throughput: 1.2 MB/s, " "ue_container_Address: 10.20.30.40, [RF_SNR: 5.1 dB, RF_PWR: -11 "
"ue_container_Address: 10.20.30.40, [RF_SNR: 5.1 dB, RF_PWR: -11 " "dBm][RF_SNR: 10.1 dB, RF_PWR: -20 dBm]][ue_container_Throughput: 10.2 "
"dBm][RF_SNR: 10.1 dB, RF_PWR: -20 dBm]][ue_container_Throughput: 10.2 " "MB/s, ue_container_Address: 10.20.30.41, [RF_SNR: 20.1 dB, RF_PWR: -30 "
"MB/s, ue_container_Address: 10.20.30.41, [RF_SNR: 20.1 dB, RF_PWR: -30 " "dBm][RF_SNR: 30.1 dB, RF_PWR: -40 dBm]]]]: Text 88\n";
"dBm][RF_SNR: 30.1 dB, RF_PWR: -40 dBm]]]]: Text 88\n";
ASSERT_EQ(result, expected); ASSERT_EQ(result, expected);
@ -255,17 +233,12 @@ when_log_entry_with_context_and_message_is_passed_then_context_is_formatted()
int main() int main()
{ {
TEST_FUNCTION(when_fully_filled_log_entry_then_everything_is_formatted); TEST_FUNCTION(when_fully_filled_log_entry_then_everything_is_formatted);
TEST_FUNCTION( TEST_FUNCTION(when_log_entry_without_name_is_passed_then_name_is_not_formatted);
when_log_entry_without_name_is_passed_then_name_is_not_formatted);
TEST_FUNCTION(when_log_entry_without_tag_is_passed_then_tag_is_not_formatted); TEST_FUNCTION(when_log_entry_without_tag_is_passed_then_tag_is_not_formatted);
TEST_FUNCTION( TEST_FUNCTION(when_log_entry_without_context_is_passed_then_context_is_not_formatted);
when_log_entry_without_context_is_passed_then_context_is_not_formatted); TEST_FUNCTION(when_log_entry_with_hex_dump_is_passed_then_hex_dump_is_formatted);
TEST_FUNCTION( TEST_FUNCTION(when_log_entry_with_only_context_is_passed_then_context_is_formatted);
when_log_entry_with_hex_dump_is_passed_then_hex_dump_is_formatted); TEST_FUNCTION(when_log_entry_with_context_and_message_is_passed_then_context_is_formatted);
TEST_FUNCTION(
when_log_entry_with_only_context_is_passed_then_context_is_formatted);
TEST_FUNCTION(
when_log_entry_with_context_and_message_is_passed_then_context_is_formatted);
return 0; return 0;
} }

Loading…
Cancel
Save