Improved logging API

motis-project · Jan 16, 2025 · a03e915 · a03e915
1 parent 3457d43
commit a03e915
Show file tree

Hide file tree

Showing 5 changed files with 72 additions and 78 deletions.
diff --git a/docs/index.rst b/docs/index.rst
@@ -17,9 +17,13 @@ This is the documentation for the **utl** (utility) module.
 Logging
 -------
 
-The simplest way to produce log lines is to use the ``logF()`` macro::
+The simplest way to produce log lines is to use the ``log()`` function::
 
-  logF(info, "Simple message");
+  #include "utl/logging.h"
+
+  using namespace utl;
+
+  log(llvl::info, "Simple message");
 
 The following log levels are supported:
 
@@ -35,17 +39,20 @@ error
 Advanced usage
 ^^^^^^^^^^^^^^
 
-By default, ``logF()`` inserts the current filename & line number in the log line.
-However, you can use ``log()`` to specify your own **context** ::
+You can insert variables in the message by using ``{}`` and passing them as extra arguments
+(formatting is performed by the `fmt <https://fmt.dev>` library)::
+
+  log(llvl::info, "String={} Int={}", "Hello", 42);
+
+You can specify a **context** string::
 
-  log(info, "http.get.resource", "Details");
+  log(llvl::info, "Message").ctx("http.get.resource");
 
-You can also insert variables in the message by using ``{}`` and passing them as extra arguments::
+You can specify **metadata**::
 
-  logF(info, "String={} Int={}", "Hello", 42);
+  log(llvl::info, "Message").metadata("key", "value");
 
 API details
 ^^^^^^^^^^^
-Under the hood, the ``log()`` & ``logF()`` macros use the ``utl::log()`` function:
 
 .. doxygenfunction:: utl::log
diff --git a/include/utl/logging.h b/include/utl/logging.h
@@ -7,40 +7,28 @@
 #include <chrono>
 #include <iomanip>
 #include <iostream>
+#include <source_location>
 #include <sstream>
 #include <string>
 
 #include "fmt/core.h"
 #include "fmt/ostream.h"
 
-#define STRINGIFY(x) STRINGIFY_(x)
-#define STRINGIFY_(x) #x
-
-#define FILE_AND_LINE (__FILE__ ":" STRINGIFY(__LINE__))
-#if defined(_WIN32)
-#define FILE_AND_LINE_SHORT                                        \
-  (strrchr(FILE_AND_LINE, '\\') ? strrchr(FILE_AND_LINE, '\\') + 1 \
-                                : FILE_AND_LINE)
-#else
-#define FILE_AND_LINE_SHORT                                      \
-  (strrchr(FILE_AND_LINE, '/') ? strrchr(FILE_AND_LINE, '/') + 1 \
-                               : FILE_AND_LINE)
-#endif
-
 namespace utl {
 
-enum class log_level { debug, info, error };
+/// Log level
+enum class llvl { debug, info, error };
 
-constexpr char const* to_str(log_level const level) {
+constexpr char const* to_str(llvl const level) {
   switch (level) {
-    case log_level::debug: return "debug";
-    case log_level::info: return "info";
-    case log_level::error: return "error";
+    case llvl::debug: return "debug";
+    case llvl::info: return "info";
+    case llvl::error: return "error";
   }
   return "";
 }
 
-static log_level s_verbosity;
+static llvl s_verbosity;
 
 inline std::string now() {
   using clock = std::chrono::system_clock;
@@ -57,46 +45,44 @@ inline std::string now() {
   return ss.str();
 }
 
-/// Produce a new log line at the given `level`, with the given prefix `ctx` and
-/// message
-template <typename... Args>
-void log(log_level const level, char const* ctx,
-         fmt::format_string<Args...> fmt_str, Args&&... args) {
-  if (level >= ::utl::s_verbosity) {
-    fmt::print(std::clog, "{time} [{level}] [{ctx}] {msg}\n",
-               fmt::arg("time", now()), fmt::arg("level", to_str(level)),
-               fmt::arg("ctx", ctx),
-               fmt::arg("msg", fmt::format(fmt::runtime(fmt_str),
-                                           std::forward<Args>(args)...)));
-  }
-}
+/// Produce a new log line at the given `level`, with the given prefix `ctx` and message
+template <typename... T>
+struct log {
+    log(llvl const level, fmt::format_string<T...> fmt_str, const T&&... args) //, std::source_location const& loc = std::source_location::current())
+            : level_{level},
+              // loc_{loc},
+              ctx_{nullptr},
+              msg_{fmt::format(fmt_str, std::forward<T>(args)...)}
+    {}
+
+    ~log() {
+        if (level_ >= utl::s_verbosity) {
+            fmt::print(std::clog, "{time} [{level}] [{file}:{line} {fn}] {ctx} {msg}\n",
+                    fmt::arg("time", now()),
+                    fmt::arg("level", to_str(level_)),
+                    // fmt::arg("file", loc_.file_name()),
+                    // fmt::arg("line", loc_.line()),
+                    // fmt::arg("fn", loc_.function_name()),
+                    fmt::arg("ctx", ctx_ ? (string("[") + string(ctx_) + string("]")) : ""),
+                    fmt::arg("msg", msg_);
+        }
+    }
+
+    void ctx(char const* ctx) {
+        ctx_ = ctx;
+    }
+
+    void metadata(std::initializer_list<std::pair<std::string_view, std::string_view>>&& metadata) {
+        metadata_ = std::move(metadata);
+    }
+
+    llvl level_;
+    // std::source_location loc_;
+    char const* ctx_;
+    std::string msg_;
+    std::initializer_list<std::pair<std::string_view, std::string_view>> metadata_;
+};
 
 }  // namespace utl
 
-// clang-format off
-#define _IS_MSVC _MSC_VER && CMAKE_C_COMPILER != clang-cl
-// clang-format on
-
-/**
- * Shorthand to invoke utl::log without specifying the namespace
- */
-#if _IS_MSVC
-#define log(level, ctx, fmt_str, ...) \
-  utl::log(utl::log_level::##level, ctx, fmt_str, __VA_ARGS__)
-#else
-#define log(level, ctx, fmt_str, ...) \
-  utl::log(utl::log_level::level, ctx, fmt_str, ##__VA_ARGS__)
-#endif
-
-/**
- * Invoke utl::log using the current C++ filename & line number as ctx
- */
-#if _IS_MSVC
-#define logF(level, fmt_str, ...) \
-  log(level, FILE_AND_LINE_SHORT, fmt_str, __VA_ARGS__)
-#else
-#define logF(level, fmt_str, ...) \
-  log(level, FILE_AND_LINE_SHORT, fmt_str, ##__VA_ARGS__)
-#endif
-
 #endif  // LOGGING_HEADER
diff --git a/include/utl/parallel_for.h b/include/utl/parallel_for.h
@@ -160,7 +160,7 @@ inline errors_t parallel_for(
       jobs.size(),
       [&](auto const idx) {
         if (idx % mod == 0) {
-          logF(info, "{} {}/{}", desc, idx, jobs.size());
+          log(llvl::info, "{} {}/{}", desc, idx, jobs.size());
         }
         func(jobs[idx]);
       },

diff --git a/src/timer.cc b/src/timer.cc
@@ -6,7 +6,7 @@ namespace utl {
 
 scoped_timer::scoped_timer(std::string name)
     : name_{std::move(name)}, start_{std::chrono::steady_clock::now()} {
-  logF(info, "[{}] starting", name);
+  log(llvl::info, "[{}] starting", name);
 }
 
 scoped_timer::~scoped_timer() {
@@ -15,7 +15,7 @@ scoped_timer::~scoped_timer() {
   double t =
       static_cast<double>(duration_cast<microseconds>(stop - start_).count()) /
       1000.0;
-  logF(info, "[{}] finished ({}ms)", name_, t);
+  log(llvl::info, "[{}] finished ({}ms)", name_, t);
 }
 
 void scoped_timer::print(std::string_view const message) const {
@@ -24,12 +24,12 @@ void scoped_timer::print(std::string_view const message) const {
   double const t =
       static_cast<double>(duration_cast<microseconds>(stop - start_).count()) /
       1000.0;
-  logF(info, "[{}] {} ({}ms)", name_, message, t);
+  log(llvl::info, "[{}] {} ({}ms)", name_, message, t);
 }
 
 manual_timer::manual_timer(std::string name)
     : name_{std::move(name)}, start_{std::chrono::steady_clock::now()} {
-  logF(info, "[{}] starting", name_);
+  log(llvl::info, "[{}] starting", name_);
 }
 
 void manual_timer::stop_and_print() const {
@@ -38,7 +38,7 @@ void manual_timer::stop_and_print() const {
   double t =
       static_cast<double>(duration_cast<microseconds>(stop - start_).count()) /
       1000.0;
-  logF(info, "[{}] finished ({}ms)", name_, t);
+  log(llvl::info, "[{}] finished ({}ms)", name_, t);
 }
 
 void manual_timer::print(std::string_view const message) const {
@@ -47,7 +47,7 @@ void manual_timer::print(std::string_view const message) const {
   double const t =
       static_cast<double>(duration_cast<microseconds>(stop - start_).count()) /
       1000.0;
-  logF(info, "[{}] {} ({}ms)", name_, message, t);
+  log(llvl::info, "[{}] {} ({}ms)", name_, message, t);
 }
 
 }  // namespace utl
diff --git a/test/logging_test.cc b/test/logging_test.cc
@@ -4,10 +4,11 @@
 #include "utl/logging.h"
 
 using ::testing::MatchesRegex;
+using namespace utl;
 
 TEST(log, basic_usage) {
   testing::internal::CaptureStderr();
-  logF(info, "Simple message");
+  log(llvl::info, "Simple message");
   EXPECT_THAT(
       testing::internal::GetCapturedStderr(),
       MatchesRegex(
@@ -16,15 +17,15 @@ TEST(log, basic_usage) {
 
 TEST(log, specifying_ctx) {
   testing::internal::CaptureStderr();
-  log(info, "MyCtx", "Message");
+  log(llvl::info, "Message").ctx("MyCtx");
   EXPECT_THAT(testing::internal::GetCapturedStderr(),
               MatchesRegex(".+T.+Z \\[info\\] \\[MyCtx\\] Message\n"));
 };
 
 TEST(log, formatting_parameters) {
   testing::internal::CaptureStderr();
-  log(info, "MyCtx", "String={} Int={}", "Hello", 42);
+  log(llvl::info, "String={} Int={}", "Hello", 42);
   EXPECT_THAT(
       testing::internal::GetCapturedStderr(),
-      MatchesRegex(".+T.+Z \\[info\\] \\[MyCtx\\] String=Hello Int=42\n"));
+      MatchesRegex(".+T.+Z \\[info\\] String=Hello Int=42\n"));
 };