diff --git a/CMakeLists.txt b/CMakeLists.txt index 21577e5084..3344ac4042 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -71,6 +71,7 @@ option(SPDLOG_BUILD_TESTS_HO "Build tests using the header only version" OFF) # bench options option(SPDLOG_BUILD_BENCH "Build benchmarks (Requires https://github.com/google/benchmark.git to be installed)" OFF) +option(SPDLOG_GOOGLEBENCHMARK_URL "Url of googlebenchmark git repository" https://github.com/google/benchmark.git) # sanitizer options option(SPDLOG_SANITIZE_ADDRESS "Enable address sanitizer in tests" OFF) @@ -119,6 +120,7 @@ option( SPDLOG_NO_ATOMIC_LEVELS "prevent spdlog from using of std::atomic log levels (use only if your code never modifies log levels concurrently" OFF) +option(SPDLOG_NO_STRUCTURED_SPDLOG "Turn off structured support for a small speed increase" OFF) option(SPDLOG_DISABLE_DEFAULT_LOGGER "Disable default logger creation" OFF) # clang-tidy @@ -231,6 +233,7 @@ foreach( SPDLOG_NO_THREAD_ID SPDLOG_NO_TLS SPDLOG_NO_ATOMIC_LEVELS + SPDLOG_NO_STRUCTURED_SPDLOG SPDLOG_DISABLE_DEFAULT_LOGGER SPDLOG_USE_STD_FORMAT) if(${SPDLOG_OPTION}) diff --git a/README.md b/README.md index caac8f6ce9..d66b2b8794 100644 --- a/README.md +++ b/README.md @@ -2,7 +2,104 @@ Very fast, header-only/compiled, C++ logging library. [![Build Status](https://app.travis-ci.com/gabime/spdlog.svg?branch=v1.x)](https://app.travis-ci.com/gabime/spdlog)  [![Build status](https://ci.appveyor.com/api/projects/status/d2jnxclg20vd0o50?svg=true&branch=v1.x)](https://ci.appveyor.com/project/gabime/spdlog) [![Release](https://img.shields.io/github/release/gabime/spdlog.svg)](https://github.com/gabime/spdlog/releases/latest) -## Install +## Using Structured spdlog +```c++ +#include "spdlog/structured_spdlog.h" +#include "spdlog/json_formatter.h" + +int main() +{ + // Output structured data + spdlog::info({{"field1","value1"}, {"field2",2.0}}, "Log fields and values"); + //--> [2022-01-19 15:52:03.301] [info] Log fields and values field1:value1 field2:2.000000 + + // Set up a json formatter. Not required, but very useful for parsing logs + spdlog::set_formatter(std::make_unique()); + SPDLOG_INFO({{"field1","value2"}, {"field2",4.0}}, "JSON logging is good for fields"); + //--> {"time":"2022-01-19T15:52:03.301814-08:00", "level":"info", + // "msg":"JSON logging is good for fields", "src_loc":"example.cpp:56", + // "field1":"value2", "field2":4.000000} + + // Put current context on the stack and have it included in subsequent log statements + { + spdlog::context ctx({{"txn_id",12292338}}); + SPDLOG_INFO("Starting txn"); + //--> {"time":..., "msg":"Starting txn", "txn_id":12292338} + } + + // Put your favorite pattern fields into the json + spdlog::set_formatter(spdlog::json_formatter::make_unique( + {{"thread_id","%t",spdlog::json_field_type::NUMERIC}, {"msg","%v"}})); + { + spdlog::context ctx({{"txn_id",60841}}); + SPDLOG_INFO("New txn"); + //--> {"thread_id":10468, "msg":"New txn", "txn_id":60841} + } + + // Carry contexts across your favorite thread pool + spdlog::context inner_ctx({{"outer","ctx"}}); + auto ctx_snapshot=spdlog::snapshot_context_fields(); + std::thread thread = spdlog::details::make_unique( + [ctx_snapshot] { + spdlog::context thread_ctx({{"position",1}}); + spdlog::info("Started a thread"); + spdlog::replacement_context ctx(ctx_snapshot); // Replace the existing contexts + spdlog::context thread_ctx2({{"superposition",2}}); + spdlog::info("In a thread"); + }); + thread.join(); + //--> {"msg":"Started a thread", "position":1} + // {"msg":"In a thread", "superposition":2, "outer":"ctx"} + +} +``` + +## Structured performance +(on a 24-CPU Broadwell VM) + +Summary: +* If compiled with -DSPDLOG_NO_STRUCTURED_SPDLOG=ON, no statistically significant slowdown + +* w/ structured on, ~6% slowdown (independent of depth of stack contexts) +* w/ json output, ~50% slowdown (definite room for optimizations) + +| benchmark | origin/v1.x | structured_v0
-DSPDLOG_NO_STRUCTURED_SPDLOG=ON | structured_v0 | +|-------------|-------------|----------------|-------------| +| basic_st | 2.34M/s ± 0.04M/s | 2.25M/s ± 0.05M/s | 2.20M/s ± 0.06M/s | +| 1x basic_mt | 2.15M/s ± 0.04M/s | 2.09M/s ± 0.04M/s | 2.03M/s ± 0.05M/s | +| 4x basic_mt | 1.24M/s ± 0.02M/s | 1.24M/s ± 0.02M/s | 1.20M/s ± 0.02M/s | +| field_st | | | 2.28M/s ± 0.04M/s | +| 1ctx_st | | | 2.25M/s ± 0.04M/s | +| 10ctx_st | | | 2.24M/s ± 0.04M/s | +| field_json_st | | | 1.15M/s ± 0.02M/s | + +* All numbers reported with 95% confidence interval over 100 runs +* Run with ``cmake -DCMAKE_BUILD_TYPE=Release -DSPDLOG_BUILD_BENCH=ON && make -j && for i in {1..100}; do bench/bench > "/tmp/spdlog-`git rev-parse HEAD`-`date +%s`"; done`` +* New benchmarks: + * field_st: Implement ``bench_fields`` with ``log->log(spdlog::source_loc{}, spdlog::level::info, {{"msg number",i}}, "Hello logger");`` + * 1ctx: ``spdlog::context ctx({{"ctx", 1}}); bench_fields(iters, basic_1ctx_st);`` + * 10ctx: ``spdlog::context ctx1({{"ctx", 1}}); spdlog::context ctx2({{"ctx", 1}}); ...; bench_fields(iters, basic_10ctx_st);`` + * field_json_st: ``basic_json_st->set_formatter(spdlog::details::make_unique()); bench_fields(iters, basic_json_st);`` + +## Structured TODOs + +* Optimization + * Current implementation was written for efficiency, but not optimized yet +* wchar support +* Complete the set of convenience functions + * e.g. ``spdlog::log(level, fields, msg);`` + + * Note that it intentionally doesn't expose Fields + fmt+args; we've found it's generally best to move things to fields whenever you touch the logging + * If you really need to you can use ``fmt::format()`` for the message +* Test on all combinations of builds + * Tested on linux, with and without -DSPDLOG_NO_STRUCTURED_SPDLOG set + +* Custom tags w/ JSON formatter +* Printing objects to JSON +* Format specifiers for floats on the stack + + +## Install #### Header only version Copy the include [folder](https://github.com/gabime/spdlog/tree/v1.x/include/spdlog) to your build tree and use a C++11 compiler. @@ -12,7 +109,7 @@ $ git clone https://github.com/gabime/spdlog.git $ cd spdlog && mkdir build && cd build $ cmake .. && make -j ``` - + see example [CMakeLists.txt](https://github.com/gabime/spdlog/blob/v1.x/example/CMakeLists.txt) on how to use. ## Platforms @@ -53,30 +150,30 @@ $ cmake .. && make -j * Log filtering - log levels can be modified in runtime as well as in compile time. * Support for loading log levels from argv or from environment var. * [Backtrace](#backtrace-support) support - store debug messages in a ring buffer and display later on demand. - + ## Usage samples #### Basic usage ```c++ #include "spdlog/spdlog.h" -int main() +int main() { spdlog::info("Welcome to spdlog!"); spdlog::error("Some error message with arg: {}", 1); - + spdlog::warn("Easy padding in numbers like {:08d}", 12); spdlog::critical("Support for int: {0:d}; hex: {0:x}; oct: {0:o}; bin: {0:b}", 42); spdlog::info("Support for floats {:03.2f}", 1.23456); spdlog::info("Positional args are {1} {0}..", "too", "supported"); spdlog::info("{:<30}", "left aligned"); - + spdlog::set_level(spdlog::level::debug); // Set global log level to debug - spdlog::debug("This message should be displayed.."); - + spdlog::debug("This message should be displayed.."); + // change log pattern spdlog::set_pattern("[%H:%M:%S %z] [%n] [%^---%L---%$] [thread %t] %v"); - + // Compile time log levels // define SPDLOG_ACTIVE_LEVEL to desired level SPDLOG_TRACE("Some trace message with param {}", 42); @@ -92,8 +189,8 @@ int main() void stdout_example() { // create color multi threaded logger - auto console = spdlog::stdout_color_mt("console"); - auto err_logger = spdlog::stderr_color_mt("stderr"); + auto console = spdlog::stdout_color_mt("console"); + auto err_logger = spdlog::stderr_color_mt("stderr"); spdlog::get("console")->info("loggers can be retrieved from a global registry using the spdlog::get(logger_name)"); } ``` @@ -104,7 +201,7 @@ void stdout_example() #include "spdlog/sinks/basic_file_sink.h" void basic_logfile_example() { - try + try { auto logger = spdlog::basic_logger_mt("basic_logger", "logs/basic-log.txt"); } @@ -175,9 +272,9 @@ spdlog::flush_every(std::chrono::seconds(3)); #include "spdlog/stopwatch.h" void stopwatch_example() { - spdlog::stopwatch sw; + spdlog::stopwatch sw; spdlog::debug("Elapsed {}", sw); - spdlog::debug("Elapsed {:.3}", sw); + spdlog::debug("Elapsed {:.3}", sw); } ``` @@ -243,13 +340,13 @@ void async_example() // spdlog::init_thread_pool(8192, 1); // queue with 8k items and 1 backing thread. auto async_file = spdlog::basic_logger_mt("async_file_logger", "logs/async_log.txt"); // alternatively: - // auto async_file = spdlog::create_async("async_file_logger", "logs/async_log.txt"); + // auto async_file = spdlog::create_async("async_file_logger", "logs/async_log.txt"); } ``` --- -#### Asynchronous logger with multi sinks +#### Asynchronous logger with multi sinks ```c++ #include "spdlog/sinks/stdout_color_sinks.h" #include "spdlog/sinks/rotating_file_sink.h" @@ -264,7 +361,7 @@ void multi_sink_example2() spdlog::register_logger(logger); } ``` - + --- #### User defined types ```c++ @@ -289,7 +386,7 @@ void user_defined_example() --- #### User defined flags in the log pattern -```c++ +```c++ // Log patterns can contain custom flags. // the following example will add new flag '%*' - which will be bound to a instance. #include "spdlog/pattern_formatter.h" @@ -309,7 +406,7 @@ public: }; void custom_flags_example() -{ +{ auto formatter = std::make_unique(); formatter->add_flag('*').set_pattern("[%n] [%*] [%^%l%$] %v"); spdlog::set_formatter(std::move(formatter)); @@ -330,7 +427,7 @@ void err_handler_example() ``` --- -#### syslog +#### syslog ```c++ #include "spdlog/sinks/syslog_sink.h" void syslog_example() @@ -341,7 +438,7 @@ void syslog_example() } ``` --- -#### Android example +#### Android example ```c++ #include "spdlog/sinks/android_sink.h" void android_example() @@ -377,7 +474,7 @@ $ ./example --- #### Log file open/close event handlers ```c++ -// You can get callbacks from spdlog before/after log file has been opened or closed. +// You can get callbacks from spdlog before/after log file has been opened or closed. // This is useful for cleanup procedures or for adding someting the start/end of the log files. void file_events_example() { @@ -387,7 +484,7 @@ void file_events_example() handlers.after_open = [](spdlog::filename_t filename, std::FILE *fstream) { fputs("After opening\n", fstream); }; handlers.before_close = [](spdlog::filename_t filename, std::FILE *fstream) { fputs("Before closing\n", fstream); }; handlers.after_close = [](spdlog::filename_t filename) { spdlog::info("After closing {}", filename); }; - auto my_logger = spdlog::basic_logger_st("some_logger", "logs/events-sample.txt", true, handlers); + auto my_logger = spdlog::basic_logger_st("some_logger", "logs/events-sample.txt", true, handlers); } ``` @@ -437,16 +534,16 @@ Below are some [benchmarks](https://github.com/gabime/spdlog/blob/v1.x/bench/ben [info] Messages : 1,000,000 [info] Threads : 10 [info] Queue : 8,192 slots -[info] Queue memory : 8,192 x 272 = 2,176 KB +[info] Queue memory : 8,192 x 272 = 2,176 KB [info] ------------------------------------------------- -[info] +[info] [info] ********************************* [info] Queue Overflow Policy: block [info] ********************************* [info] Elapsed: 1.70784 secs 585,535/sec [info] Elapsed: 1.69805 secs 588,910/sec [info] Elapsed: 1.7026 secs 587,337/sec -[info] +[info] [info] ********************************* [info] Queue Overflow Policy: overrun [info] ********************************* @@ -462,5 +559,3 @@ Documentation can be found in the [wiki](https://github.com/gabime/spdlog/wiki/1 --- Thanks to [JetBrains](https://www.jetbrains.com/?from=spdlog) for donating product licenses to help develop **spdlog** - - diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 144f50b830..69d73a8b79 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -17,10 +17,10 @@ if(NOT benchmark_FOUND) message(STATUS "Downloading GoogleBenchmark") include(FetchContent) - # disable tests - set(BENCHMARK_ENABLE_TESTING OFF CACHE INTERNAL "") + # disable tests + set(BENCHMARK_ENABLE_TESTING OFF CACHE INTERNAL "") # Do not build and run googlebenchmark tests - FetchContent_Declare(googlebenchmark GIT_REPOSITORY https://github.com/google/benchmark.git GIT_TAG v1.6.0) + FetchContent_Declare(googlebenchmark GIT_REPOSITORY ${SPDLOG_GOOGLEBENCHMARK_URL} GIT_TAG v1.6.0) FetchContent_MakeAvailable(googlebenchmark) else() message(FATAL_ERROR "GoogleBenchmark is missing. Use CMake >= 3.11 or download it") diff --git a/bench/bench.cpp b/bench/bench.cpp index 8a46837a6a..d5309c1530 100644 --- a/bench/bench.cpp +++ b/bench/bench.cpp @@ -30,6 +30,13 @@ void bench(int howmany, std::shared_ptr log); void bench_mt(int howmany, std::shared_ptr log, size_t thread_count); +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +#include "spdlog/structured_spdlog.h" +#include "spdlog/json_formatter.h" + +void bench_fields(int howmany, std::shared_ptr log); +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + // void bench_default_api(int howmany, std::shared_ptr log); // void bench_c_string(int howmany, std::shared_ptr log); @@ -108,6 +115,37 @@ void bench_single_threaded(int iters) empty_logger_tracing->set_level(spdlog::level::off); empty_logger_tracing->enable_backtrace(32); bench(iters, empty_logger_tracing); + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + spdlog::info(""); + auto basic_field_st = spdlog::basic_logger_st("basic_fields_st", "logs/basic_fields_st.log", true); + bench_fields(iters, basic_field_st); + + auto basic_json_st = spdlog::basic_logger_st("basic_json_st", "logs/basic_json_st.log", true); + basic_json_st->set_formatter(spdlog::details::make_unique()); + bench_fields(iters, basic_json_st); + + { + spdlog::context ctx({{"ctx", 1}}); + auto basic_1ctx_st = spdlog::basic_logger_st("basic_1ctx_st", "logs/basic_1ctx_st.log", true); + bench_fields(iters, basic_1ctx_st); + } + + { + spdlog::context ctx0({{"ctx", 1}}); + spdlog::context ctx1({{"ctx", 1}}); + spdlog::context ctx2({{"ctx", 1}}); + spdlog::context ctx3({{"ctx", 1}}); + spdlog::context ctx4({{"ctx", 1}}); + spdlog::context ctx5({{"ctx", 1}}); + spdlog::context ctx6({{"ctx", 1}}); + spdlog::context ctx7({{"ctx", 1}}); + spdlog::context ctx8({{"ctx", 1}}); + spdlog::context ctx9({{"ctx", 1}}); + auto basic_10ctx_st = spdlog::basic_logger_st("basic_10ctx_st", "logs/basic_10ctx_st.log", true); + bench_fields(iters, basic_10ctx_st); + } +#endif } int main(int argc, char *argv[]) @@ -145,6 +183,30 @@ int main(int argc, char *argv[]) return EXIT_SUCCESS; } + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +void bench_fields(int howmany, std::shared_ptr log) +{ + using std::chrono::duration; + using std::chrono::duration_cast; + using std::chrono::high_resolution_clock; + + auto start = high_resolution_clock::now(); + for (auto i = 0; i < howmany; ++i) + { + log->log(spdlog::source_loc{}, spdlog::level::info, {{"msg number",i}}, "Hello logger"); + } + + auto delta = high_resolution_clock::now() - start; + auto delta_d = duration_cast>(delta).count(); + + spdlog::info(spdlog::fmt_lib::format( + std::locale("en_US.UTF-8"), "{:<30} Elapsed: {:0.2f} secs {:>16L}/sec", log->name(), delta_d, int(howmany / delta_d))); + spdlog::drop(log->name()); +} +#endif + + void bench(int howmany, std::shared_ptr log) { using std::chrono::duration; @@ -245,4 +307,4 @@ void bench_c_string(int howmany, std::shared_ptr log) spdlog::info("{:<30} Elapsed: {:0.2f} secs {:>16}/sec", log->name(), delta_d, int(howmany / delta_d)); } -*/ \ No newline at end of file +*/ diff --git a/cmake/pch.h.in b/cmake/pch.h.in deleted file mode 100644 index a5f9415071..0000000000 --- a/cmake/pch.h.in +++ /dev/null @@ -1,258 +0,0 @@ -// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. -// Distributed under the MIT License (http://opensource.org/licenses/MIT) - -#pragma once - -// details/pattern_formatter-inl.h -// fmt/bin_to_hex.h -// fmt/bundled/format-inl.h -#include - -// details/file_helper-inl.h -// details/os-inl.h -// fmt/bundled/core.h -// fmt/bundled/posix.h -// logger-inl.h -// sinks/daily_file_sink.h -// sinks/stdout_sinks.h -#include - -// details/os-inl.h -// fmt/bundled/posix.h -#include - -// details/os-inl.h -// details/pattern_formatter-inl.h -// fmt/bundled/core.h -// fmt/bundled/format-inl.h -#include - -// details/os-inl.h -// details/os.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// fmt/bundled/chrono.h -// sinks/daily_file_sink.h -// sinks/rotating_file_sink-inl.h -#include - -// fmt/bundled/format-inl.h -#include - -// fmt/bundled/format-inl.h -#include - -// fmt/bundled/format-inl.h -// fmt/bundled/format.h -#include - -// fmt/bundled/format-inl.h -#include - -// details/file_helper-inl.h -// fmt/bundled/format.h -// fmt/bundled/posix.h -// sinks/rotating_file_sink-inl.h -#include - -// details/circular_q.h -// details/thread_pool-inl.h -// fmt/bundled/format-inl.h -#include - -// async_logger-inl.h -// cfg/helpers-inl.h -// log_levels.h -// common.h -// details/file_helper-inl.h -// details/log_msg.h -// details/os-inl.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/registry-inl.h -// details/registry.h -// details/tcp_client-windows.h -// details/tcp_client.h -// fmt/bundled/core.h -// sinks/android_sink.h -// sinks/ansicolor_sink.h -// sinks/basic_file_sink.h -// sinks/daily_file_sink.h -// sinks/dup_filter_sink.h -// sinks/msvc_sink.h -// sinks/ringbuffer_sink.h -// sinks/rotating_file_sink-inl.h -// sinks/rotating_file_sink.h -// sinks/syslog_sink.h -// sinks/tcp_sink.h -// sinks/win_eventlog_sink.h -// sinks/wincolor_sink.h -// spdlog.h: -#include - -// cfg/helpers-inl.h -// fmt/bundled/chrono.h -#include - -// fmt/bundled/ostream.h -// sinks/ostream_sink.h -#include - -// cfg/log_levels.h -// details/registry-inl.h -// details/registry.h -#include - -// details/circular_q.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/thread_pool.h -// fmt/bundled/compile.h -// logger.h -// sinks/dist_sink.h -// sinks/ringbuffer_sink.h -// sinks/win_eventlog_sink.h -#include - -// details/os-inl.h -// details/pattern_formatter-inl.h -// sinks/ansicolor_sink.h -// sinks/syslog_sink.h -// sinks/systemd_sink.h -// sinks/wincolor_sink.h -#include - -// details/file_helper-inl.h -// details/file_helper.h -// sinks/rotating_file_sink-inl.h -#include - -// details/os-inl.h -// fmt/bundled/format.h -// fmt/bundled/printf.h -#include - -// common.h -// details/backtracer.h -// details/null_mutex.h -#include - -// common.h -// details/backtracer.h -// details/null_mutex.h -#include - -// common.h -#include - -// common.h -#include - -// common.h -// details/fmt_helper.h -// fmt/bundled/core.h -// fmt/bundled/ranges.h -#include - -// cfg/helpers-inl.h -// details/null_mutex.h -// details/pattern_formatter-inl.h -#include - -// async.h -// async_logger-inl.h -// common.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/registry-inl.h -// details/registry.h -// details/thread_pool.h -// fmt/bundled/format.h -// sinks/ansicolor_sink.h -// sinks/base_sink-inl.h -// sinks/dist_sink.h -// sinks/stdout_sinks-inl.h -// sinks/wincolor_sink.h -// spdlog.h -#include - -// async.h -// common.h -// details/backtracer.h -// details/periodic_worker.h -// details/registry-inl.h -// details/registry.h -// details/thread_pool.h -// sinks/tcp_sink.h -// spdlog.h -#include - -// details/mpmc_blocking_q.h -// details/periodic_worker.h -#include - -// details/os-inl.h -// fmt/bundled/format.h -// fmt/bundled/printf.h -// sinks/dist_sink.h -#include - -// common.h -// details/file_helper-inl.h -// details/fmt_helper.h -// details/os-inl.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/periodic_worker.h -// details/registry-inl.h -// details/registry.h -// details/thread_pool.h -// fmt/bundled/chrono.h -// sinks/android_sink.h -// sinks/daily_file_sink.h -// sinks/dup_filter_sink.h -// sinks/rotating_file_sink-inl.h -// sinks/rotating_file_sink.h -// sinks/tcp_sink.h -// spdlog.h -#include - -// details/file_helper-inl.h -// details/os-inl.h -// details/pattern_formatter-inl.h -// details/periodic_worker.h -// details/thread_pool.h -// sinks/android_sink.h -#include - -// async.h -// details/backtracer.h -// details/console_globals.h -// details/mpmc_blocking_q.h -// details/pattern_formatter-inl.h -// details/periodic_worker.h -// details/registry.h -// sinks/android_sink.h -// sinks/ansicolor_sink.h -// sinks/basic_file_sink.h -// sinks/daily_file_sink.h -// sinks/dist_sink.h -// sinks/dup_filter_sink.h -// sinks/msvc_sink.h -// sinks/null_sink.h -// sinks/ostream_sink.h -// sinks/ringbuffer_sink.h -// sinks/rotating_file_sink-inl.h -// sinks/rotating_file_sink.h -// sinks/tcp_sink.h -// sinks/win_eventlog_sink.h -// sinks/wincolor_sink.h -// -// color_sinks.cpp -// file_sinks.cpp -// spdlog.cpp -// stdout_sinks.cpp -#include - -// spdlog -#include \ No newline at end of file diff --git a/example/example.cpp b/example/example.cpp index c1251b1bed..a87db8a117 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -27,6 +27,7 @@ void file_events_example(); void replace_default_logger_example(); #include "spdlog/spdlog.h" +#include "spdlog/json_formatter.h" #include "spdlog/cfg/env.h" // support for loading levels from the environment variable #include "spdlog/fmt/ostr.h" // support for user defined types @@ -49,6 +50,13 @@ int main(int, char *[]) spdlog::set_level(spdlog::level::trace); // Set specific logger's log level spdlog::debug("This message should be displayed.."); +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // Structured data + spdlog::info({{"field1","value1"}, {"field2",2.0}}, "You can output data with fields and values"); + spdlog::set_formatter(spdlog::details::make_unique()); + SPDLOG_INFO({{"field1","value2"}, {"field2",4.0}}, "JSON logging is good for fields"); +#endif + // Customize msg format for all loggers spdlog::set_pattern("[%H:%M:%S %z] [%^%L%$] [thread %t] %v"); spdlog::info("This an info message with custom format"); @@ -199,8 +207,8 @@ void vector_example() spdlog::info("Vector example: {}", vec); } -#else -void vector_example() {} +#else +void vector_example() {} #endif // ! DSPDLOG_USE_STD_FORMAT @@ -266,7 +274,7 @@ template<> struct fmt_lib::formatter : fmt_lib::formatter { auto format(my_type my, format_context &ctx) -> decltype(ctx.out()) - { + { return fmt_lib::format_to(ctx.out(), "[my_type i={}]", my.i); } }; @@ -359,9 +367,9 @@ void replace_default_logger_example() auto new_logger = spdlog::basic_logger_mt("new_default_logger", "logs/new-default-log.txt", true); spdlog::set_default_logger(new_logger); - spdlog::set_level(spdlog::level::info); + spdlog::set_level(spdlog::level::info); spdlog::debug("This message should not be displayed!"); - spdlog::set_level(spdlog::level::trace); + spdlog::set_level(spdlog::level::trace); spdlog::debug("This message should be displayed.."); spdlog::set_default_logger(old_logger); diff --git a/include/spdlog/common-inl.h b/include/spdlog/common-inl.h index 9fd2bcb547..fd26ef8526 100644 --- a/include/spdlog/common-inl.h +++ b/include/spdlog/common-inl.h @@ -79,4 +79,15 @@ SPDLOG_INLINE void throw_spdlog_ex(std::string msg) SPDLOG_THROW(spdlog_ex(std::move(msg))); } +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +namespace details { + +SPDLOG_INLINE std::shared_ptr& threadlocal_context_head() { + thread_local std::shared_ptr context_head; + return context_head; +} + +} // namespace details +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + } // namespace spdlog diff --git a/include/spdlog/common.h b/include/spdlog/common.h index 9903463c60..ab6bbf3dd7 100644 --- a/include/spdlog/common.h +++ b/include/spdlog/common.h @@ -15,6 +15,7 @@ #include #include #include +#include #ifdef SPDLOG_USE_STD_FORMAT # include @@ -319,6 +320,60 @@ struct file_event_handlers {} }; +// Cover all fundamental types for C++ plus string_view +// see https://en.cppreference.com/w/cpp/language/types +// This would be better handled by a C++14 std::variant type, but we want to stay C++11-compatible +enum class FieldValueType { + STRING_VIEW, + SHORT, USHORT, INT, UINT, LONG, ULONG, LONGLONG, ULONGLONG, + BOOL, + CHAR, UCHAR, WCHAR, + FLOAT, DOUBLE, LONGDOUBLE +}; + +struct Field { + spdlog::string_view_t name; + FieldValueType value_type; + union { + string_view_t string_view_; + short short_; unsigned short ushort_; int int_; unsigned int uint_; + long long_; unsigned long ulong_; long long longlong_; unsigned long long ulonglong_; + bool bool_; + char char_; unsigned char uchar_; wchar_t wchar_; + float float_; double double_; long double longdouble_; + }; + Field(const string_view_t &field_name, FieldValueType field_type) : + name(field_name), value_type(field_type) {}; + Field() : name{}, value_type(FieldValueType::INT), int_(0) {} + + Field(const string_view_t &field_name, string_view_t val): name(field_name), value_type(FieldValueType::STRING_VIEW), string_view_(val) {} + Field(const string_view_t &field_name, short val): name(field_name), value_type(FieldValueType::SHORT), short_ (val) {} + Field(const string_view_t &field_name, unsigned short val): name(field_name), value_type(FieldValueType::USHORT), ushort_ (val) {} + Field(const string_view_t &field_name, int val): name(field_name), value_type(FieldValueType::INT), int_ (val) {} + Field(const string_view_t &field_name, unsigned int val): name(field_name), value_type(FieldValueType::UINT), uint_ (val) {} + Field(const string_view_t &field_name, long val): name(field_name), value_type(FieldValueType::LONG), long_ (val) {} + Field(const string_view_t &field_name, unsigned long val): name(field_name), value_type(FieldValueType::ULONG), ulong_ (val) {} + Field(const string_view_t &field_name, long long val): name(field_name), value_type(FieldValueType::LONGLONG), longlong_ (val) {} + Field(const string_view_t &field_name, unsigned long long val): name(field_name), value_type(FieldValueType::ULONGLONG), ulonglong_ (val) {} + Field(const string_view_t &field_name, bool val): name(field_name), value_type(FieldValueType::BOOL), bool_ (val) {} + Field(const string_view_t &field_name, char val): name(field_name), value_type(FieldValueType::CHAR), char_ (val) {} + Field(const string_view_t &field_name, unsigned char val): name(field_name), value_type(FieldValueType::UCHAR), uchar_ (val) {} + Field(const string_view_t &field_name, wchar_t val): name(field_name), value_type(FieldValueType::WCHAR), wchar_ (val) {} + Field(const string_view_t &field_name, float val): name(field_name), value_type(FieldValueType::FLOAT), float_ (val) {} + Field(const string_view_t &field_name, double val): name(field_name), value_type(FieldValueType::DOUBLE), double_ (val) {} + Field(const string_view_t &field_name, long double val): name(field_name), value_type(FieldValueType::LONGDOUBLE), longdouble_ (val) {} + + // Catch static strings so they don't get converted to bools + template + Field(const string_view_t &field_name, const char (&val)[N]): name(field_name), value_type(FieldValueType::STRING_VIEW), string_view_{val, N-1} {} +}; +using F=Field; + +namespace details { + class context_data; + SPDLOG_API std::shared_ptr& threadlocal_context_head(); +} + namespace details { // make_unique support for pre c++14 diff --git a/include/spdlog/details/log_msg-inl.h b/include/spdlog/details/log_msg-inl.h index c6e8a7e04f..4fccc2d30e 100644 --- a/include/spdlog/details/log_msg-inl.h +++ b/include/spdlog/details/log_msg-inl.h @@ -13,7 +13,7 @@ namespace spdlog { namespace details { SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::source_loc loc, string_view_t a_logger_name, - spdlog::level::level_enum lvl, spdlog::string_view_t msg) + spdlog::level::level_enum lvl, spdlog::string_view_t msg, const Field * fields, size_t field_count) : logger_name(a_logger_name) , level(lvl) , time(log_time) @@ -22,15 +22,37 @@ SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::s #endif , source(loc) , payload(msg) +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + , field_data(const_cast(fields)) + , field_data_count(field_count) + , context_field_data(threadlocal_context_head()) +#endif +{ +#ifdef SPDLOG_NO_STRUCTURED_SPDLOG + // Prevent unused argument warning + (void) fields; + (void) field_count; +#endif +} + +SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::source_loc loc, string_view_t a_logger_name, + spdlog::level::level_enum lvl, spdlog::string_view_t msg) + : log_msg(log_time, loc, a_logger_name, lvl, msg, nullptr, 0) {} SPDLOG_INLINE log_msg::log_msg( spdlog::source_loc loc, string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg) - : log_msg(os::now(), loc, a_logger_name, lvl, msg) + : log_msg(os::now(), loc, a_logger_name, lvl, msg, nullptr, 0) +{} + +SPDLOG_INLINE log_msg::log_msg( + spdlog::source_loc loc, string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg, + const Field * fields, size_t field_count) + : log_msg(os::now(), loc, a_logger_name, lvl, msg, fields, field_count) {} SPDLOG_INLINE log_msg::log_msg(string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg) - : log_msg(os::now(), source_loc{}, a_logger_name, lvl, msg) + : log_msg(os::now(), source_loc{}, a_logger_name, lvl, msg, nullptr, 0) {} } // namespace details diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index fed51abdf6..9bb0af63df 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -8,10 +8,13 @@ namespace spdlog { namespace details { +class context_data; struct SPDLOG_API log_msg { log_msg() = default; + log_msg(log_clock::time_point log_time, source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg, const Field * fields, size_t field_count); log_msg(log_clock::time_point log_time, source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg); + log_msg(source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg, const Field * fields, size_t field_count); 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; @@ -28,6 +31,12 @@ struct SPDLOG_API log_msg source_loc source; string_view_t payload; + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + Field *field_data{nullptr}; + size_t field_data_count{0}; + std::shared_ptr context_field_data; +#endif // SPDLOG_NO_STRUCTURED_SPDLOG }; } // namespace details } // namespace spdlog diff --git a/include/spdlog/details/log_msg_buffer-inl.h b/include/spdlog/details/log_msg_buffer-inl.h index 84d83dc2fe..251c4e2a3a 100644 --- a/include/spdlog/details/log_msg_buffer-inl.h +++ b/include/spdlog/details/log_msg_buffer-inl.h @@ -13,6 +13,18 @@ namespace details { SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg &orig_msg) : log_msg{orig_msg} { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + field_buffer = std::vector(field_data, field_data + field_data_count); + field_data = field_buffer.data(); + + // Copy strings from fields + for (size_t i=0; i < field_data_count; i++) { + buffer.append(field_data[i].name); + if (field_data[i].value_type == FieldValueType::STRING_VIEW) { + buffer.append(field_data[i].string_view_.begin(), field_data[i].string_view_.end()); + } + } +#endif buffer.append(logger_name.begin(), logger_name.end()); buffer.append(payload.begin(), payload.end()); update_string_views(); @@ -21,12 +33,24 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg &orig_msg) SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) : log_msg{other} { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + field_buffer = std::vector(field_data, field_data + field_data_count); + field_data = field_buffer.data(); + + // Copy strings from fields + for (size_t i=0; i < field_data_count; i++) { + buffer.append(field_data[i].name); + if (field_data[i].value_type == FieldValueType::STRING_VIEW) { + buffer.append(field_data[i].string_view_.begin(), field_data[i].string_view_.end()); + } + } +#endif buffer.append(logger_name.begin(), logger_name.end()); buffer.append(payload.begin(), payload.end()); update_string_views(); } -SPDLOG_INLINE log_msg_buffer::log_msg_buffer(log_msg_buffer &&other) SPDLOG_NOEXCEPT : log_msg{other}, buffer{std::move(other.buffer)} +SPDLOG_INLINE log_msg_buffer::log_msg_buffer(log_msg_buffer &&other) SPDLOG_NOEXCEPT : log_msg{other}, buffer{std::move(other.buffer)}, field_buffer{std::move(other.field_buffer)} { update_string_views(); } @@ -36,6 +60,7 @@ SPDLOG_INLINE log_msg_buffer &log_msg_buffer::operator=(const log_msg_buffer &ot log_msg::operator=(other); buffer.clear(); buffer.append(other.buffer.data(), other.buffer.data() + other.buffer.size()); + field_buffer = other.field_buffer; update_string_views(); return *this; } @@ -44,14 +69,29 @@ SPDLOG_INLINE log_msg_buffer &log_msg_buffer::operator=(log_msg_buffer &&other) { log_msg::operator=(other); buffer = std::move(other.buffer); + field_buffer = std::move(other.field_buffer); update_string_views(); return *this; } SPDLOG_INLINE void log_msg_buffer::update_string_views() { - logger_name = string_view_t{buffer.data(), logger_name.size()}; - payload = string_view_t{buffer.data() + logger_name.size(), payload.size()}; + size_t offset = 0; +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + for (size_t i=0; i < field_data_count; i++) { + field_data[i].name = string_view_t{buffer.data() + offset, field_data[i].name.size()}; + offset += field_data[i].name.size(); + if (field_data[i].value_type == FieldValueType::STRING_VIEW) { + auto &data_value = field_data[i].string_view_; + data_value = {buffer.data() + offset, data_value.size()}; + offset += data_value.size(); + } + } +#endif + logger_name = string_view_t{buffer.data() + offset, logger_name.size()}; + offset += logger_name.size(); + payload = string_view_t{buffer.data() + offset, payload.size()}; + offset += payload.size(); } } // namespace details diff --git a/include/spdlog/details/log_msg_buffer.h b/include/spdlog/details/log_msg_buffer.h index 8105506563..118388cf16 100644 --- a/include/spdlog/details/log_msg_buffer.h +++ b/include/spdlog/details/log_msg_buffer.h @@ -5,6 +5,8 @@ #include +#include + namespace spdlog { namespace details { @@ -14,6 +16,8 @@ namespace details { class SPDLOG_API log_msg_buffer : public log_msg { memory_buf_t buffer; + std::vector field_buffer; + void update_string_views(); public: diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h new file mode 100644 index 0000000000..a9ce87b078 --- /dev/null +++ b/include/spdlog/json_formatter-inl.h @@ -0,0 +1,370 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#ifndef SPDLOG_HEADER_ONLY +# include +#endif + +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include + +namespace spdlog { + +namespace details { + +SPDLOG_CONSTEXPR char hex_digits[] = "0123456789abcdef"; + +// 5 -> escape to \uXXXXX +// 1 -> escape to \n, \r or the like +// 0 -> do not escape +SPDLOG_CONSTEXPR uint8_t extra_chars_lookup[256] = { + 5, 5, 5, 5, 5, 5, 5, 5, 1, 1, 1, 5, 1, 1, 5, 5, // 0x0x + 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, // 0x1x + 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x2x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x3x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x4x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, // 0x5x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x6x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x7x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x8x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x9x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xAx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xBx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xCx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xDx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xEx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xFx +}; + +// TODO: make a version that can take a list of [start,end] ranges; we can then +// write the whole line to the dest buffer and do one pass of escaping: count, +// realloc, escape + +SPDLOG_INLINE void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset) +{ + // Check to see if we have any characters that must be escaped + // See https://datatracker.ietf.org/doc/html/rfc8259#section-7 + // Note that only certain ASCII characters need to be; all non-ASCII + // utf-8 codepoints can pass right through + + // TODO: Note that this code is not correct for UTF-8 inputs; if we have + // a UTF-8 value like \u03a3 (Sigma), the UTF-8 encoding is \xCE\xA3, and + // it will be encoded as \u00ce\u00a3 rather than \u03a3. + // + // We need to actually parse the input as utf-8 codepoints to + // know which bytes are consumed in multi-byte utf-8 encodings + // See https://datatracker.ietf.org/doc/html/rfc3629 + + // The checks are implemented by looking up in the extra_chars table that encodes + // how many extra bytes we need for each character. 0 implies it doesn't + // need to be escaped; 1 means that it's an encoded caracter (\r, \n, and the like), + // and 5 means that it needs to be unicode-escaped (\u0000). + + // TODO: widechar support + static_assert(sizeof(dest[0]) ==1, "Wide chars are not supported by escape_to_end yet"); + + size_t extra_chars_required = 0; + for (auto i=start_offset; i < dest.size(); i++) { + uint8_t c = dest[i]; // need to make it unsigned + extra_chars_required += extra_chars_lookup[c]; + } + if (extra_chars_required == 0) { + return; // No escaping to be done + } + size_t original_size = dest.size(); + dest.resize(dest.size() + extra_chars_required); + + // Work backward until done + auto start_p = dest.data() + start_offset; + auto src_p = dest.data() + original_size - 1; + auto dest_p = src_p + extra_chars_required; + while (src_p >= start_p) { + uint8_t c = *src_p; + switch(extra_chars_lookup[c]) { + case 5: + dest_p -= 5; + dest_p[0] = '\\'; + dest_p[1] = 'u'; + dest_p[2] = '0'; + dest_p[3] = '0'; + dest_p[4] = hex_digits[(c >> 4) & 0x0f]; + dest_p[5] = hex_digits[c & 0x0f]; + break; + case 1: + dest_p -= 1; + dest_p[0] = '\\'; + switch(c) { + case '"': + dest_p[1] = '"'; + break; + case '\\': + dest_p[1] = '\\'; + break; + case '\b': + dest_p[1] = 'b'; + break; + case '\f': + dest_p[1] = 'f'; + break; + case '\n': + dest_p[1] = 'n'; + break; + case '\r': + dest_p[1] = 'r'; + break; + case '\t': + dest_p[1] = 't'; + break; + default: + abort(); // should never get here + } // switch(c) + break; + case 0: + *dest_p = c; + break; + default: + abort(); // should never get here + } // switch(extra_chars_lookup[c]) + + dest_p--; + src_p--; + } + + // They should have converged at the start + assert(dest_p == src_p); +} + +SPDLOG_INLINE bool pattern_needs_escaping(string_view_t pattern) +{ + // As a performance boost, we know that there are certain spdlog %.. patterns + // that can only produce non-escaped ASCII. We can write those values + // straight out to the JSON without needing to check them for illegal characters + // + // Scan the user-supplied pattern to see if it contains text that needs to be + // escaped, or a pattern that is not in the KNOWN_CLEAN list + // We check for needs-to-be-escaped characters by checking the extra_chars table; + // anything that requires 0 extra chars doesn't need to be escaped. + + constexpr char KNOWN_CLEAN_PATTERNS[] = "LtplLaAbBcCYDxmdHIMSefFprRTXzE%#oiuO"; + + for (size_t i=0; i < pattern.size(); i++) { + // Check for % flags + uint8_t c = static_cast(pattern[i]); + if (c == '%' && i < pattern.size() - 1) { + i++; + c = static_cast(pattern[i]); + + // TODO(opt): make this a hash lookup + bool flag_char_is_clean = false; + for (auto clean: KNOWN_CLEAN_PATTERNS) { + if (clean == c) { + flag_char_is_clean = true; + break; + } + } + if (!flag_char_is_clean) { + return true; + } + } + + // Check for json-escaped character in pattern + if (extra_chars_lookup[c] != 0) { + return true; + } + } + return false; +} + +SPDLOG_INLINE pattern_field::pattern_field(string_view_t name, string_view_t pattern, json_field_type field_type, pattern_time_type pattern_time_type_) : + formatter_(details::make_unique(to_string(pattern), pattern_time_type_, "")), + field_type_(field_type) +{ + // TODO - make this all one pattern {"name": "%v", }; since we know the prefix and suffix length, + // we can do one call to format(), then escape just the questionable data + memory_buf_t value_prefix; + value_prefix.push_back('"'); + fmt_helper::append_string_view(name, value_prefix); + escape_to_end(value_prefix, 1); + value_prefix.push_back('"'); + value_prefix.push_back(':'); + value_prefix_ = to_string(value_prefix); + + output_needs_escaping_ = pattern_needs_escaping(pattern); +} + +SPDLOG_INLINE pattern_field::pattern_field(const std::string &value_prefix, formatter* formatter, json_field_type field_type, bool output_needs_escaping) : + value_prefix_(value_prefix), formatter_(std::move(formatter->clone())), field_type_(field_type), output_needs_escaping_(output_needs_escaping) +{ +} + +SPDLOG_INLINE std::unique_ptr pattern_field::clone() const +{ + // Clone using private ctor + return std::unique_ptr(new pattern_field(value_prefix_, formatter_.get(), field_type_, output_needs_escaping_)); +} + +SPDLOG_INLINE void pattern_field::format(const details::log_msg &msg, memory_buf_t &dest) +{ + fmt_helper::append_string_view(value_prefix_, dest); + if (field_type_ == json_field_type::STRING) { + dest.push_back('"'); + } + size_t start_offset = dest.size(); + formatter_->format(msg, dest); + if (output_needs_escaping_) { + escape_to_end(dest, start_offset); + } + if (field_type_ == json_field_type::STRING) { + fmt_helper::append_string_view("\", ", dest); + } else { + fmt_helper::append_string_view(", ", dest); + } +} + +} // namespace details + + +SPDLOG_INLINE json_formatter::json_formatter(std::initializer_list field_defs, pattern_time_type time_type, std::string eol) : + pattern_time_type_(time_type), + eol_(eol) +{ + for (auto &def: field_defs) { + fields_.emplace_back(details::make_unique(def.field_name, def.pattern, def.field_type, pattern_time_type_)); + } +} + +SPDLOG_INLINE json_formatter::json_formatter(pattern_time_type time_type, std::string eol) : + pattern_time_type_(time_type), + eol_(eol) +{ + add_default_fields(); +} + +SPDLOG_INLINE json_formatter& json_formatter::add_default_fields() +{ + return add_field("time", ISO8601_FLAGS).add_field("level", "%l"). + add_field("msg", "%v", json_field_type::STRING).add_field("src_loc", "%s:%#"); +} + +SPDLOG_INLINE json_formatter &json_formatter::add_field(std::string field_name, std::string pattern, json_field_type field_type) +{ + fields_.emplace_back( + details::make_unique(field_name, pattern, field_type, pattern_time_type_) + ); + return *this; +} + + +SPDLOG_INLINE std::unique_ptr json_formatter::clone() const +{ + auto result = make_unique({}, pattern_time_type_, eol_); + for (auto &field: fields_) { + result->fields_.emplace_back(std::move(field->clone())); + } + return result; +} + +SPDLOG_INLINE bool is_numeric(FieldValueType type) +{ + switch(type) { + case FieldValueType::STRING_VIEW: return false; + case FieldValueType::SHORT: return true; + case FieldValueType::USHORT: return true; + case FieldValueType::INT: return true; + case FieldValueType::UINT: return true; + case FieldValueType::LONG: return true; + case FieldValueType::ULONG: return true; + case FieldValueType::LONGLONG: return true; + case FieldValueType::ULONGLONG: return true; + case FieldValueType::BOOL: return true; // in JSON, it is + case FieldValueType::CHAR: return false; + case FieldValueType::UCHAR: return true; + case FieldValueType::WCHAR: return false; + case FieldValueType::FLOAT: return true; + case FieldValueType::DOUBLE: return true; + case FieldValueType::LONGDOUBLE: return true; + } + abort(); // we should never get here +} + +SPDLOG_INLINE void json_formatter::format_data_field(const Field &field, spdlog::memory_buf_t &dest) +{ +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // TODO: should we keep a hash table of field names->escaped field names? + // If the same fields keep cropping up and have to be escaped again and again it could have + // a small but noticeable impact on performance + dest.push_back('"'); + size_t offset = dest.size(); + details::fmt_helper::append_string_view(field.name, dest); + details::escape_to_end(dest, offset); + dest.push_back('"'); + dest.push_back(':'); + + bool numeric = is_numeric(field.value_type); + if (!numeric) { + dest.push_back('"'); + } + size_t start_offset = dest.size(); + details::append_value(field, dest); + details::escape_to_end(dest, start_offset); + if (!numeric) { + dest.push_back('"'); + } + + dest.push_back(','); + dest.push_back(' '); +#else + (void) field; + (void) dest; +#endif +} + + +SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_buf_t &dest) +{ + // TODO: support custom flag formatters + // TODO: all safe fields can be compiled into one pattern formatter + + memory_buf_t buffer; + dest.push_back('{'); + + for (auto &field_ptr: fields_) { + field_ptr->format(msg, dest); + } + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + for (size_t i=0; i < msg.field_data_count; i++) { + format_data_field(msg.field_data[i], dest); + } + if (msg.context_field_data) { + for (auto &field: *msg.context_field_data) { + format_data_field(field, dest); + } + } +#endif + + // Strip trailing space if it's there + if (dest[dest.size() -1] == ' ') { + dest.resize(dest.size() -1); + } + if (dest[dest.size() -1] == ',') { + dest.resize(dest.size() -1); + } + dest.push_back('}'); + details::fmt_helper::append_string_view(eol_, dest); +} + +} // namespace spdlog diff --git a/include/spdlog/json_formatter.h b/include/spdlog/json_formatter.h new file mode 100644 index 0000000000..7ed5966724 --- /dev/null +++ b/include/spdlog/json_formatter.h @@ -0,0 +1,96 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#include +#include +#include +#include +#include + +#include +#include +#include + +#include +#include +#include + +namespace spdlog { + +SPDLOG_CONSTEXPR char ISO8601_FLAGS[] = "%Y-%m-%dT%H:%M:%S.%f%z"; +enum class json_field_type {NUMERIC, STRING}; + +namespace details { + void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset); + bool pattern_needs_escaping(string_view_t pattern); + + class pattern_field { + public: + pattern_field(string_view_t name, string_view_t pattern, json_field_type field_type, pattern_time_type pattern_time_type_); + + pattern_field(const pattern_field &other) = delete; + pattern_field &operator=(const pattern_field &other) = delete; + + void format(const details::log_msg &msg, memory_buf_t &dest); + + std::unique_ptr clone() const; + private: + pattern_field(const std::string &name, formatter* formatter, json_field_type field_type, bool output_needs_escaping); + std::string value_prefix_; // {"name":} + std::unique_ptr formatter_; + json_field_type field_type_; + bool output_needs_escaping_; + }; +} // namespace details + +struct pattern_field_definition { + std::string field_name; + std::string pattern; + json_field_type field_type = json_field_type::STRING; + + pattern_field_definition(string_view_t name, string_view_t pattern, json_field_type field_type = json_field_type::STRING) : + field_name(to_string(name)), pattern(to_string(pattern)), field_type(field_type) {} +}; +class SPDLOG_API json_formatter final : public formatter +{ +public: + + // With default fields + json_formatter(pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + + // With user-selected fields + json_formatter(std::initializer_list fields, pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + + // Can't pass initializer_list through std::forward calls, including std::make_unique + static std::unique_ptr make_unique(std::initializer_list fields, pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol) + { + return std::unique_ptr(new json_formatter(fields, time_type, eol)); + } + + json_formatter &add_field(std::string field_name, std::string pattern, json_field_type field_type = json_field_type::STRING); + json_formatter &add_default_fields(); + + + json_formatter(const json_formatter &other) = delete; + json_formatter &operator=(const json_formatter &other) = delete; + + std::unique_ptr clone() const override; + void format(const details::log_msg &msg, memory_buf_t &dest) override; + +private: + void format_data_field(const Field &field, spdlog::memory_buf_t &dest); + + pattern_time_type pattern_time_type_; + std::string eol_; + + std::vector> fields_; +}; + + +} // namespace spdlog + +#ifdef SPDLOG_HEADER_ONLY +# include "json_formatter-inl.h" +#endif diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index a8abae419a..39c89168f4 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -84,10 +84,15 @@ class SPDLOG_API logger logger &operator=(logger other) SPDLOG_NOEXCEPT; void swap(spdlog::logger &other) SPDLOG_NOEXCEPT; + void log(source_loc loc, level::level_enum lvl, std::initializer_list fields, string_view_t msg) + { + log_(loc, lvl, fields.begin(), fields.size(), msg); + } + template void log(source_loc loc, level::level_enum lvl, format_string_t fmt, Args &&... args) { - log_(loc, lvl, fmt, std::forward(args)...); + log_(loc, lvl, nullptr, 0, fmt, std::forward(args)...); } template @@ -180,7 +185,7 @@ class SPDLOG_API logger template void log(source_loc loc, level::level_enum lvl, wformat_string_t fmt, Args &&... args) { - log_(loc, lvl, fmt, std::forward(args)...); + log_(loc, lvl, {}, fmt, std::forward(args)...); } template @@ -261,6 +266,49 @@ class SPDLOG_API logger } #endif +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + void log(level::level_enum lvl, std::initializer_list fields, string_view_t msg) + { + log(source_loc{}, lvl, fields, msg); + } + + template + void trace(std::initializer_list fields, const T &msg) + { + log(level::trace, fields, msg); + } + + template + void debug(std::initializer_list fields, const T &msg) + { + log(level::debug, fields, msg); + } + + template + void info(std::initializer_list fields, const T &msg) + { + log(level::info, fields, msg); + } + + template + void warn(std::initializer_list fields, const T &msg) + { + log(level::warn, fields, msg); + } + + template + void error(std::initializer_list fields, const T &msg) + { + log(level::err, fields, msg); + } + + template + void critical(std::initializer_list fields, const T &msg) + { + log(level::critical, fields, msg); + } +#endif + template void trace(const T &msg) { @@ -353,7 +401,7 @@ class SPDLOG_API logger // common implementation for after templated public api has been resolved template - void log_(source_loc loc, level::level_enum lvl, string_view_t fmt, Args &&... args) + void log_(source_loc loc, level::level_enum lvl, const Field * fields, size_t num_fields, string_view_t fmt, Args &&... args) { bool log_enabled = should_log(lvl); bool traceback_enabled = tracer_.enabled(); @@ -369,7 +417,7 @@ class SPDLOG_API logger memory_buf_t buf; fmt::detail::vformat_to(buf, fmt, fmt::make_format_args(std::forward(args)...)); #endif - details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); + details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size()), fields, num_fields); log_it_(log_msg, log_enabled, traceback_enabled); } SPDLOG_LOGGER_CATCH(loc) diff --git a/include/spdlog/pattern_formatter-inl.h b/include/spdlog/pattern_formatter-inl.h index ec727032b9..f106975ee8 100644 --- a/include/spdlog/pattern_formatter-inl.h +++ b/include/spdlog/pattern_formatter-inl.h @@ -12,6 +12,10 @@ #include #include #include +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +#include +#endif + #include #include @@ -691,6 +695,44 @@ class v_formatter final : public flag_formatter } }; +template +class V_formatter final : public flag_formatter +{ +public: + explicit V_formatter(padding_info padinfo) + : flag_formatter(padinfo) + {} + + // This is just a starting MVP. We probably want to be able to + // customize separators, color the key and value separately, + // and lots more expressive things + void format(const details::log_msg &msg, const std::tm &, memory_buf_t &dest) override + { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // TODO: padding + for (size_t i=0; i < msg.field_data_count; i++) { + dest.push_back(' '); + Field &field = msg.field_data[i]; + fmt_helper::append_string_view(field.name, dest); + dest.push_back(':'); + details::append_value(field, dest); + } + + if (msg.context_field_data) { + for (auto &field: *msg.context_field_data) { + dest.push_back(' '); + fmt_helper::append_string_view(field.name, dest); + dest.push_back(':'); + details::append_value(field, dest); + } + } +#else + (void) msg; + (void) dest; +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + } +}; + class ch_formatter final : public flag_formatter { public: @@ -1005,6 +1047,17 @@ class full_formatter final : public flag_formatter } // fmt_helper::append_string_view(msg.msg(), dest); fmt_helper::append_string_view(msg.payload, dest); + + // structured fields +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + for (size_t i=0; i < msg.field_data_count; i++) { + dest.push_back(' '); + Field &field = msg.field_data[i]; + fmt_helper::append_string_view(field.name, dest); + dest.push_back(':'); + details::append_value(field, dest); + } +#endif } private: @@ -1119,6 +1172,10 @@ SPDLOG_INLINE void pattern_formatter::handle_flag_(char flag, details::padding_i formatters_.push_back(details::make_unique>(padding)); break; + case ('V'): // the structured fields + formatters_.push_back(details::make_unique>(padding)); + break; + case ('a'): // weekday formatters_.push_back(details::make_unique>(padding)); break; diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index 65d3e9d59f..18d7f585b1 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -187,6 +187,40 @@ inline void log(level::level_enum lvl, const T &msg) default_logger_raw()->log(lvl, msg); } +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +inline void trace(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::trace, fields, msg); +} + +inline void debug(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::debug, fields, msg); +} + +inline void info(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::info, fields, msg); +} + +inline void warn(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::warn, fields, msg); +} + +inline void error(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::err, fields, msg); +} + +inline void critical(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::critical, fields, msg); +} +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + + + #ifdef SPDLOG_WCHAR_TO_UTF8_SUPPORT template inline void log(source_loc source, level::level_enum lvl, wformat_string_t fmt, Args &&... args) diff --git a/include/spdlog/structured_spdlog-inl.h b/include/spdlog/structured_spdlog-inl.h new file mode 100644 index 0000000000..befdbf5b90 --- /dev/null +++ b/include/spdlog/structured_spdlog-inl.h @@ -0,0 +1,192 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + +#ifndef STRUCTURED_SPDLOG_INL_H +#define STRUCTURED_SPDLOG_INL_H + +#pragma once + +#ifndef SPDLOG_HEADER_ONLY +# include +#endif + +// TODO(opt): static field names on the stack +// Rather than passing std::initializer_list, I intuit that we should be able to construct +// templates such that log_ eventually gets passed a std::array && names and +// std::array && values. The names will in most cases be constexprs and can be built +// entirely in the data segment, and the runtime will be copying only the value data in + +namespace spdlog { +namespace details { + +SPDLOG_INLINE void append_value(const Field &field, memory_buf_t &dest) +{ + switch(field.value_type) { + case FieldValueType::STRING_VIEW: { + auto *buf_ptr = field.string_view_.data(); + dest.append(buf_ptr, buf_ptr + field.string_view_.size()); + break; + } + case FieldValueType::SHORT: details::fmt_helper::append_int(field.short_, dest); break; + case FieldValueType::USHORT: details::fmt_helper::append_int(field.ushort_, dest); break; + case FieldValueType::INT: details::fmt_helper::append_int(field.int_, dest); break; + case FieldValueType::UINT: details::fmt_helper::append_int(field.uint_, dest); break; + case FieldValueType::LONG: details::fmt_helper::append_int(field.long_, dest); break; + case FieldValueType::ULONG: details::fmt_helper::append_int(field.ulong_, dest); break; + case FieldValueType::LONGLONG: details::fmt_helper::append_int(field.longlong_, dest); break; + case FieldValueType::ULONGLONG: details::fmt_helper::append_int(field.ulonglong_, dest); break; + + case FieldValueType::BOOL: details::fmt_helper::append_string_view(field.bool_?"true":"false", dest); break; + + case FieldValueType::CHAR: dest.push_back(field.char_); break; + case FieldValueType::UCHAR: details::fmt_helper::append_int(field.uchar_, dest); break; + case FieldValueType::WCHAR: details::fmt_helper::append_string_view(std::to_string(field.wchar_), dest); break; + + // TODO: optimize these to only have at most one reallocation + case FieldValueType::FLOAT: details::fmt_helper::append_string_view(std::to_string(field.float_), dest); break; + case FieldValueType::DOUBLE: details::fmt_helper::append_string_view(std::to_string(field.double_), dest); break; + case FieldValueType::LONGDOUBLE: details::fmt_helper::append_string_view(std::to_string(field.longdouble_), dest); break; + } +} + +SPDLOG_INLINE std::string value_to_string(const Field &field) +{ + memory_buf_t buf; + append_value(field, buf); + return to_string(buf); +} + + +SPDLOG_INLINE context_data::context_data(std::shared_ptr parent_fields, const Field * fields, size_t num_fields) : + parent_fields_(parent_fields), fields_(fields, fields + num_fields) +{ + // Find total required storage + size_t size = 0; + for (auto &field: fields_) { + size += field.name.size(); + if (field.value_type == FieldValueType::STRING_VIEW) { + size += field.string_view_.size(); + } + } + buffers_.resize(size); + + // Copy any string views into buffers_ and point the string view to the new copy + size_t offset = 0; + for (auto &field: fields_) { + size_t field_size = field.name.size(); + std::memcpy(&buffers_[offset], field.name.data(), field_size); + field.name = string_view_t(&buffers_[offset], field_size); + offset += field_size; + + if (field.value_type == FieldValueType::STRING_VIEW) { + field_size = field.string_view_.size(); + std::memcpy(&buffers_[offset], field.string_view_.data(), field_size); + field.string_view_ = string_view_t(&buffers_[offset], field_size); + offset += field_size; + } + } + + assert(offset == buffers_.size()); +} + +SPDLOG_INLINE context_data::~context_data() +{ + buffers_.resize(0); +} + +} // namespace details + + +// +// Contexts +// +SPDLOG_INLINE context::context(std::initializer_list fields) +{ + if (fields.size() > 0) { + std::shared_ptr& context_head = details::threadlocal_context_head(); + + context_to_restore_ = context_head; + + auto new_context_head = std::make_shared(context_head, fields.begin(), fields.size()); + context_head = new_context_head; + } else { + // Never store a link with zero fields; iterator++ needs to know that when it follows a traversal, it will + // be pointing to context_data with at least one field. + // When this goes out of context, just put the same head back + context_to_restore_ = details::threadlocal_context_head(); + } +} + +SPDLOG_INLINE context::~context() +{ + details::threadlocal_context_head() = context_to_restore_; +} + +SPDLOG_INLINE void context::reset(std::initializer_list fields) +{ + auto parent_ptr = context_to_restore_; + + if (fields.size() > 0) { + auto new_context_head = std::make_shared(parent_ptr, fields.begin(), fields.size()); + details::threadlocal_context_head() = new_context_head; + } else { + // Reset current state to the parent of the old state + details::threadlocal_context_head() = parent_ptr; + + // Never store a link with zero fields; iterator++ needs to know that when it follows a traversal, it will + // be pointing to context_data with at least one field. + // When this goes out of context, just put the same head back + context_to_restore_ = parent_ptr; + } +} + + +// context_iterators +SPDLOG_INLINE context_iterator& context_iterator::operator++() +{ + if (data_ && (++idx_ == data_->fields_.size())) { + data_ = data_->parent_fields_.get(); // may be nullptr + idx_ = 0; + } + return *this; +} + +SPDLOG_INLINE context_iterator::reference context_iterator::operator*() +{ + return data_->fields_[idx_]; +} +SPDLOG_INLINE context_iterator::pointer context_iterator::operator->() +{ + return &data_->fields_[idx_]; +} + +// snapshots +SPDLOG_INLINE details::context_snapshot snapshot_context_fields() +{ + return details::threadlocal_context_head(); +} + +SPDLOG_INLINE replacement_context::replacement_context(details::context_snapshot data, std::initializer_list fields) : + old_context_fields_(details::threadlocal_context_head()) +{ + if (fields.size() == 0) { + details::threadlocal_context_head() = data; + } else { + auto new_context_head = std::make_shared(data, fields.begin(), fields.size()); + details::threadlocal_context_head() = new_context_head; + } +} + +SPDLOG_INLINE replacement_context::~replacement_context() +{ + details::threadlocal_context_head() = old_context_fields_; +} + + +} // namespace spdlog + +#endif // STRUCTURED_SPDLOG_INL_H + +#endif // SPDLOG_NO_STRUCTURED_SPDLOG diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h new file mode 100644 index 0000000000..24d9dd0896 --- /dev/null +++ b/include/spdlog/structured_spdlog.h @@ -0,0 +1,170 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + +#ifndef STRUCTURED_SPDLOG_H +#define STRUCTURED_SPDLOG_H + +#pragma once + +#include "spdlog/common.h" + +#include + +namespace spdlog { + + +SPDLOG_API struct context_iterator +{ + /** + For formatters, walk all of the current context fields for formatting and display. + + if (msg.context_field_data) { + for (auto &field: *msg.context_field_data) { + std::cout << to_string(field.name) << "=" << spdlog::details::value_to_string(field) << " "; + } + } + **/ + using iterator_category = std::forward_iterator_tag; + using value_type = Field; + using pointer = const Field*; + using reference = const Field&; + + context_iterator(details::context_data* ctx, size_t idx) : + data_(ctx), idx_(idx) {} + + reference operator*(); + pointer operator->(); + + // Prefix increment + context_iterator& operator++(); + + // Postfix increment + context_iterator operator++(int) { context_iterator result(data_,idx_); ++result; return result; } + + friend bool operator== (const context_iterator& a, const context_iterator& b) { return a.data_ == b.data_ && a.idx_ == b.idx_; }; + friend bool operator!= (const context_iterator& a, const context_iterator& b) { return a.data_ != b.data_ || a.idx_ != b.idx_; }; + +private: + details::context_data* data_; + size_t idx_; +}; + +namespace details { + void SPDLOG_API append_value(const Field &field, memory_buf_t &dest); + std::string SPDLOG_API value_to_string(const Field &field); + + // A linked list of context_data field collections + // TODO(opt): implement caching flattened parents + // We can track how many times there has been another context that + // points to this one as a parent. As an optimization, we can accumulate all of + // the fields of the parents into fields_ when the number of children gets to 2 or 3 + // NB: If number of children gets to (very large), reset it to (something small) to guard + // against wraparound at MAX_INT + // TODO(opt): lazily use shared_ptr + // If we're not submitting to a multithreaded logger or snapshotting, we can just use raw pointers + // instead of taking the cache miss of an atomic operation in the shared_ptr. We should + // benchmark to see how much it costs us in the single-threaded case + SPDLOG_API struct context_data { + std::shared_ptr parent_fields_; + std::vector fields_; + memory_buf_t buffers_; // storage for strings in fields_ + + context_data(std::shared_ptr parent_fields, const Field * fields, size_t num_fields); + ~context_data(); + + // Iterator support + context_iterator begin() { return context_iterator(this, 0); } + context_iterator end() { return context_iterator(nullptr, 0); } + }; + + // Thread-local context fields + using context_snapshot = std::shared_ptr; +} + + +/** + Using context to represent the state of the application: + + NOTE: it is important that the context variable has a name, or it will go out of scope immediately. + RIGHT: spdlog::context ctx({{"field",value}}); + WRONG: spdlog::context({{"field",value}}); + + void bar() { + spdlog::info({{"processing", "bar"}}); // prints "program:contextfield_demo running:foo processing:bar" + std::thread th([ctx_snapshot=snapshot_context_fields()] { // copy the threadlocal context for use in another thread + spdlog::replacement_context ctx(ctx_snapshot); // Log with ctx_snapshot while ctx is still on the stack + spdlog::info({{"function", "in_thread"}}); // prints "program:contextfield_demo running:foo function:in_thread" + }); + th.join(); + } + + void foo() { + spdlog::context ctx({{"running", "foo"}}); // set context on the stack; goes away after ctx goes out of scope + bar(); + } + + int main() { + // Text output + spdlog::default_logger()->set_pattern("%v%V"); // or just use the default + foo(); + + // JSON output + auto formatter = spdlog::json_formatter::make_unique({{"program", "contextfield_demo"}}); // process-wide context + spdlog::default_logger()->set_formatter(formatter); + foo(); + } +**/ +class SPDLOG_API context final { +public: + context(std::initializer_list fields); + ~context(); + + // Replaces the contents of a context already on the stack with new values. + // Useful for putting at the top of a processing loop to hold the context and + // only reset it when something changes + void reset(std::initializer_list fields); +private: + std::shared_ptr context_to_restore_; +}; + +/** + replacement_context replaces the current thread's entire context with a snapshot + of context from another thread. Useful when work is being passed via lambdas to + threadpools for execution. + + Can also be constructed with additional context for this instance. For example: + spdlog::context ctx({{"outer", "val"}}); + std::thread th([ctx_snapshot=snapshot_context_fields()] { // copy the threadlocal context for use in another thread + spdlog::replacement_context ctx(ctx_snapshot, + {{"thread_id"}, std::this_thread::get_id()}}); // Restore outer context with additional local context + spdlog::info({{"function", "in_thread"}}); // prints "outer:val thread_id:169 function:in_thread" + }); + th.join(); + +**/ +SPDLOG_API details::context_snapshot snapshot_context_fields(); +class SPDLOG_API replacement_context final { +public: + // Temporarily replace the current thread-local context with a snapshot from another thread + replacement_context(details::context_snapshot data) : replacement_context(data, {}) {}; + + // Temporarily replace the current thread-local context with a snapshot from another thread + // and additional local context + replacement_context(details::context_snapshot data, std::initializer_list fields); + ~replacement_context(); +private: + std::shared_ptr old_context_fields_; +}; + + +} // namespace spdlog + +#endif // STRUCTURED_SPDLOG_H +#endif // NO_STRUCTURED_SPDLOG + + +#ifdef SPDLOG_HEADER_ONLY +# include "structured_spdlog-inl.h" +#endif diff --git a/src/spdlog.cpp b/src/spdlog.cpp index c86d8fff59..60c1fcac42 100644 --- a/src/spdlog.cpp +++ b/src/spdlog.cpp @@ -10,7 +10,9 @@ #include #include #include +#include #include +#include #include #include #include diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 7fe4791eb1..ad1055221c 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -19,6 +19,7 @@ set(SPDLOG_UTESTS_SOURCES test_daily_logger.cpp test_misc.cpp test_eventlog.cpp + test_json_formatter.cpp test_pattern_formatter.cpp test_async.cpp test_registry.cpp @@ -32,6 +33,7 @@ set(SPDLOG_UTESTS_SOURCES test_backtrace.cpp test_create_dir.cpp test_cfg.cpp + test_structured.cpp test_time_point.cpp test_stopwatch.cpp) diff --git a/tests/includes.h b/tests/includes.h index 7285873a81..43df8734e3 100644 --- a/tests/includes.h +++ b/tests/includes.h @@ -23,4 +23,6 @@ #include "spdlog/sinks/ostream_sink.h" #include "spdlog/sinks/rotating_file_sink.h" #include "spdlog/sinks/stdout_color_sinks.h" -#include "spdlog/pattern_formatter.h" \ No newline at end of file +#include "spdlog/json_formatter.h" +#include "spdlog/pattern_formatter.h" +#include "spdlog/structured_spdlog.h" diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp new file mode 100644 index 0000000000..8c0fa9f9ac --- /dev/null +++ b/tests/test_json_formatter.cpp @@ -0,0 +1,161 @@ +#include "includes.h" +#include "test_sink.h" + +#include + +using spdlog::memory_buf_t; +using spdlog::json_field_type; +using Catch::Matchers::Matches; + +template +static std::string log_to_str(const std::string &msg, std::initializer_list fields, + std::initializer_list patterns, bool use_default_patterns = false) +{ + std::ostringstream oss; + auto oss_sink = std::make_shared(oss); + spdlog::logger oss_logger("json_tester", oss_sink); + oss_logger.set_level(spdlog::level::info); + + spdlog::json_formatter *formatter; + if (!use_default_patterns) { + formatter = new spdlog::json_formatter(patterns); + } else { + formatter = new spdlog::json_formatter(); + } + oss_logger.set_formatter(std::unique_ptr(formatter)); + oss_logger.log(spdlog::source_loc{"source.cpp", 99, "fn"}, spdlog::level::info, fields, msg); + + return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); +} + +TEST_CASE("json basic output", "[json_formatter]") +{ + // Test fields with static outputs + using JF=spdlog::pattern_field_definition; + REQUIRE(log_to_str("hello", {}, {JF{"MSG", "%v"}, JF{"SRC", "%@"}, JF{"LEVEL", "%l"}}) == R"({"MSG":"hello", "SRC":"source.cpp:99", "LEVEL":"info"})"); + + // Tests with regex outputs + REQUIRE_THAT(log_to_str("hello", {}, {{"THREAD","%t", json_field_type::NUMERIC}}), Matches(R"(\{"THREAD":[0-9]+\})")); + // ISO8601 regex lifted from https://www.myintervals.com/blog/2009/05/20/iso-8601-date-validation-that-doesnt-suck/ + // Trimmed of leading ^ and trailing $ + constexpr char ISO8601_REGEX[] = R"(([\+-]?\d{4}(?!\d{2}\b))((-?)((0[1-9]|1[0-2])(\3([12]\d|0[1-9]|3[01]))?|W([0-4]\d|5[0-2])(-?[1-7])?|(00[1-9]|0[1-9]\d|[12]\d{2}|3([0-5]\d|6[1-6])))([T\s]((([01]\d|2[0-3])((:?)[0-5]\d)?|24\:?00)([\.,]\d+(?!:))?)?(\17[0-5]\d([\.,]\d+)?)?([zZ]|([\+-])([01]\d|2[0-3]):?([0-5]\d)?)?)?)?)"; + std::string time_output_regex = std::string(R"(\{"TM":")") + std::string(ISO8601_REGEX) + std::string(R"("\})"); + REQUIRE_THAT(log_to_str("hello", {}, {{"TM", spdlog::ISO8601_FLAGS}}), Matches(time_output_regex)); + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // Fields alone + auto fields = {spdlog::F("f1", 1), spdlog::F("f2", "two"), spdlog::F("f3", 3.0), spdlog::F("f4",true)}; + REQUIRE(log_to_str("hello", fields, {}) == R"({"f1":1, "f2":"two", "f3":3.000000, "f4":true})"); + + // Fields with message + REQUIRE(log_to_str("hello", fields, {{"MSG", "%v"}}) == R"({"MSG":"hello", "f1":1, "f2":"two", "f3":3.000000, "f4":true})"); + + // Fields with context + { + spdlog::context ctx1({{"c1",10}}); + spdlog::context ctx2({{"c2",11}}); + REQUIRE(log_to_str("hello", fields, {{"MSG", "%v"}}) == R"({"MSG":"hello", "f1":1, "f2":"two", "f3":3.000000, "f4":true, "c2":11, "c1":10})"); + } + + // Default output + static const std::string DEFAULT_RESULT_REGEX = std::string("\\{") + + R"("time":")" + ISO8601_REGEX + R"(", )" + + R"("level":"info", )" + + R"("msg":"hello", )" + + R"("src_loc":"source.cpp:99", )" + + R"("f1":1, )" + + R"("f2":"two", )" + + R"("f3":3.0+, )" + + R"("f4":true})"; + REQUIRE_THAT(log_to_str("hello", fields, {}, true), Matches(DEFAULT_RESULT_REGEX)); +#endif // SPDLOG_NO_STRUCTURED_SPDLOG +} + +TEST_CASE("json escaped output", "[json_formatter]") +{ + REQUIRE(log_to_str("hello_\x1a", {}, {{"MSG", "%v"}}) == R"({"MSG":"hello_\u001a"})"); + REQUIRE(log_to_str("hello", {}, {{"MSG_\x1a", "%v"}}) == R"({"MSG_\u001a":"hello"})"); + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + auto fields = {spdlog::F("hello_\x1a", "goodbye_\x1b")}; + REQUIRE(log_to_str("", fields, {}) == R"({"hello_\u001a":"goodbye_\u001b"})"); +#endif // SPDLOG_NO_STRUCTURED_SPDLOG +} + +TEST_CASE("json escaping", "[json_formatter]") +{ + // No escaping + memory_buf_t buffer; + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("hello", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "hello"); + + // Escaping in the middle + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("hello_\x1d_goodbye", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "hello_\\u001d_goodbye"); + + // Escaping at beginning and end + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("\x1d_hello_\x1a", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "\\u001d_hello_\\u001a"); + + // Wholly escaped + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("\x1d", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "\\u001d"); + + // Null string + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == ""); + + // Special characters + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("\\\r\n\t\b\f\"", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "\\\\\\r\\n\\t\\b\\f\\\""); + + // Not escaped + constexpr size_t NUM_ESCAPED_CHARS = 39; // 32 that are <= 0x1f, and 7 that are \r, \n, etc. + buffer.resize(256 - NUM_ESCAPED_CHARS); + char *p = &buffer[0]; + for (int c=0; c <= 255; c++) { + if (c <= 0x1f || c == '"' || c == '\\' || c == '\b' || c == '\f' || c == '\n' || c == '\r' || c == '\t') + continue; + *(p++) = static_cast(c); + } + auto before = to_string(buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == before); + + // Skipping already-escaped parts + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + std::string already_done{"\\\"foo\": \""}; + spdlog::details::fmt_helper::append_string_view(already_done, buffer); + spdlog::details::fmt_helper::append_string_view("bar\n", buffer); + spdlog::details::escape_to_end(buffer, already_done.size()); + REQUIRE(to_string(buffer) == "\\\"foo\": \"bar\\n"); + +} + +TEST_CASE("json pattern needs escaping", "[json_formatter]") +{ + REQUIRE(spdlog::details::pattern_needs_escaping("%v") == true); // messages might be unicode + REQUIRE(spdlog::details::pattern_needs_escaping("%s") == true); // source files might be unicode + REQUIRE(spdlog::details::pattern_needs_escaping("%%") == false); + REQUIRE(spdlog::details::pattern_needs_escaping("") == false); + REQUIRE(spdlog::details::pattern_needs_escaping("no pattern text") == false); + REQUIRE(spdlog::details::pattern_needs_escaping(spdlog::ISO8601_FLAGS) == false); +} diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp new file mode 100644 index 0000000000..7b5f8a4ec3 --- /dev/null +++ b/tests/test_structured.cpp @@ -0,0 +1,277 @@ +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + +#include "includes.h" +#include "test_sink.h" + +#include + +#include "spdlog/details/log_msg_buffer.h" + +using spdlog::F; + + +std::string log_info(std::initializer_list fields, spdlog::string_view_t what) +{ + std::ostringstream oss; + auto oss_sink = std::make_shared(oss); + + spdlog::logger oss_logger("oss", oss_sink); + oss_logger.set_pattern("%v%V"); + oss_logger.log({}, spdlog::level::info, fields, what); + + return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); +} + +TEST_CASE("fields", "[structured]") +{ + // Can we construct fields with rvalues? + spdlog::F f_int("var", 1); + REQUIRE(f_int.value_type == spdlog::FieldValueType::INT); + + spdlog::F f_str_literal("var", "val"); + REQUIRE(f_str_literal.value_type == spdlog::FieldValueType::STRING_VIEW); + + // Can we construct fields with lvalues? + std::string str1("key"); + std::string str2("str"); + spdlog::F str_f(str1, str2); + REQUIRE(str_f.value_type == spdlog::FieldValueType::STRING_VIEW); + + // Const chars are troublesome; we really, really want the string literals to + // use their compile-time length, and std::strings to use their O(1) run-time + // length. The const char (&val)[N] and string_view constructors take care of + // those. + // If we include a const char * constructor, it will be preferred for string + // literals (unless we can arrange some template magic that works for C++11 and + // above). String literals will then have an O(n) cost, and that's no good + // If we don't include a const char * constructor, the compiler erases const char * + // to void *, which for historical resons binds to bool before anything else. + // So, for now, const char * maps to bool. :-| + const char * cstr = "str"; + auto cstr_f = spdlog::F(cstr, cstr); + REQUIRE(cstr_f.value_type == spdlog::FieldValueType::BOOL); +} + +TEST_CASE("field_logging", "[structured]") +{ + // No fields + REQUIRE(log_info({}, "Hello") == "Hello"); + + // Some fields + REQUIRE(log_info({F("k", 1)}, "Hello") == "Hello k:1"); + + // Test level calls + spdlog::info({{"field", 1}}, "Hello"); + spdlog::default_logger()->info({{"field", 2}}, "Hello"); +} + +template +void test_numeric_to_string() { + T zero_val = {}; + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", zero_val)) == std::to_string(zero_val)); + + T min_val = std::numeric_limits::min(); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", min_val)) == std::to_string(min_val)); + + T max_val = std::numeric_limits::max(); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", max_val)) == std::to_string(max_val)); + + T lowest_val = std::numeric_limits::lowest(); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", lowest_val)) == std::to_string(lowest_val)); +} + +TEST_CASE("to_string", "[structured]") +{ + // Numerics + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + + // string_view + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", "")) == ""); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", "data")) == "data"); + + // bool + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", true)) == "true"); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", false)) == "false"); + + // char + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", 'c')) == "c"); + +} + + +TEST_CASE("buffered_msg_field_copies ", "[structured]") +{ + std::unique_ptr test1; + { + auto array2 = {F("var", 1), F("var2", "two")}; + spdlog::details::log_msg test_input1(spdlog::source_loc{}, "name", spdlog::level::info, "msg", array2.begin(), array2.size()); + test1 = spdlog::details::make_unique(test_input1); + } + REQUIRE(test1->field_data_count == 2); + REQUIRE(test1->field_data[0].name == "var"); + REQUIRE(test1->field_data[0].value_type == spdlog::FieldValueType::INT); + REQUIRE(test1->field_data[0].int_ == 1); + REQUIRE(test1->field_data[1].name == "var2"); + REQUIRE(test1->field_data[1].value_type == spdlog::FieldValueType::STRING_VIEW); + REQUIRE(test1->field_data[1].string_view_ == "two"); +} + +TEST_CASE("async_structured ", "[structured]") +{ + auto test_sink = std::make_shared(); + test_sink->set_delay(std::chrono::milliseconds(1)); + size_t queue_size = 4; + size_t messages = 1024; + + auto tp = std::make_shared(queue_size, 1); + auto logger = std::make_shared("as", test_sink, tp, spdlog::async_overflow_policy::overrun_oldest); + for (size_t i = 0; i < messages; i++) + { + // Build on the stack so it's out of scope + std::string test_string("abcdefghijklmnopqrstuvwxyz"); + logger->log({}, spdlog::level::info, {F("str", test_string)}, "test msg"); + } + logger->flush(); + REQUIRE(test_sink->msg_counter() < messages); + REQUIRE(test_sink->msg_counter() > 0); + REQUIRE(tp->overrun_counter() > 0); +} + + +#if SPDLOG_ACTIVE_LEVEL != SPDLOG_LEVEL_DEBUG +# error "Invalid SPDLOG_ACTIVE_LEVEL in test. Should be SPDLOG_LEVEL_DEBUG" +#endif + +#define TEST_FILENAME "test_logs/structured_macro_log" +std::string last_line(const std::string &str) { + if (str.empty()) { + return ""; + } + auto start = str.begin(); + auto curr = str.end() - 1; + + // Skip last line + while ((*curr == '\n' || *curr == '\r') && curr != start) { + curr--; + } + auto end = curr + 1; // end is exclusive + + while (curr != start && *(curr-1) != '\n' && *(curr-1) != '\r' && curr != start) { + curr--; + } + return std::string(curr, end); +} + + +TEST_CASE("structured macros", "[structured]") +{ + prepare_logdir(); + spdlog::filename_t filename = SPDLOG_FILENAME_T(TEST_FILENAME); + + auto logger = spdlog::create("logger", filename); + logger->set_pattern("%v%V"); + logger->set_level(spdlog::level::trace); + + SPDLOG_LOGGER_TRACE(logger, {}, "Test message 1"); + SPDLOG_LOGGER_DEBUG(logger, {F("f", 0)}, "Test message 2"); + logger->flush(); + + REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 2 f:0"); + REQUIRE(count_lines(TEST_FILENAME) == 1); + + auto orig_default_logger = spdlog::default_logger(); + spdlog::set_default_logger(logger); + + SPDLOG_TRACE({}, "Test message 3"); + SPDLOG_DEBUG({F("f",1)}, "Test message 4"); + logger->flush(); + + require_message_count(TEST_FILENAME, 2); + REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 4 f:1"); + + spdlog::set_default_logger(std::move(orig_default_logger)); +} + +TEST_CASE("structured context", "[structured]") +{ + { + spdlog::context ctx({{"c1","1"}}); + REQUIRE(log_info({}, "Hello") == "Hello c1:1"); + } + + { + spdlog::context ctx1({{"c1","1"}}); + { + spdlog::context ctx2({{"c2","2"}}); + REQUIRE(log_info({}, "Hello") == "Hello c2:2 c1:1"); + } + REQUIRE(log_info({}, "Hello") == "Hello c1:1"); + } + + REQUIRE(log_info({}, "Hello") == "Hello"); +} + +TEST_CASE("structured snapshots", "[structured]") +{ + enum steps {START, CTX_REPLACED, LOG_IN_THREAD}; + std::atomic step{steps::START}; + + std::unique_ptr thread; + { + spdlog::context inner_ctx({{"c1","1"}}); + auto ctx_snapshot=spdlog::snapshot_context_fields(); + thread = spdlog::details::make_unique( + [ctx_snapshot, &step] { + spdlog::replacement_context ctx(ctx_snapshot); + step = steps::CTX_REPLACED; + while(step != LOG_IN_THREAD) ; // spin until ready + REQUIRE(log_info({}, "Hello") == "Hello c1:1"); + }); + } + // inner_ctx should be fully out of scope at this point + + // Wait for the context to be replaced in the thread, but verify + // that it doesn't affect the context of the main thread + while(step != CTX_REPLACED) ; + spdlog::context main_ctx({{"c2","2"}}); + REQUIRE(log_info({}, "Hello") == "Hello c2:2"); + + // Verify that setting the context on the main thread doesn't + // effect the test thread + step = LOG_IN_THREAD; + thread->join(); +} + + +TEST_CASE("structured snapshots with ctx", "[structured]") +{ + std::unique_ptr thread; + { + spdlog::context inner_ctx({{"c1","1"}}); + auto ctx_snapshot=spdlog::snapshot_context_fields(); + thread = spdlog::details::make_unique( + [ctx_snapshot] { + { + spdlog::replacement_context ctx(ctx_snapshot, {{"c2", 2}}); + REQUIRE(log_info({}, "Hello") == "Hello c2:2 c1:1"); + } + REQUIRE(log_info({}, "Middle") == "Middle"); + }); + } + thread->join(); + REQUIRE(log_info({}, "Bye") == "Bye"); +} + + +#endif // SPDLOG_NO_STRUCTURED_SPDLOG