WIP

Author: Lucas-C

.github/workflows/unix.yml

@@ -2,7 +2,8 @@ name: Unix Build
 
 on:
   push:
-    branches: [ master ]
+    branches: [ doc-with-doxygen-and-sphinx ]  # Temporary, restore next line before merging MR
+    # branches: [ master ]
   pull_request:
     branches: [ master ]
 
@@ -153,9 +154,11 @@ jobs:
         run: pip install -r docs/requirements.txt
       - name: Generate HTML documentation 🏗️
         run: |
-          mkdir -p public/
-          
-      - name: Deploy documentation 🚀
+          cd docs
+          doxygen
+          sphinx-build -M html . _build
+          mv _build ../public
+      - name: Deploy documentation onto GitHub Pages 🚀
         if: github.ref == 'refs/heads/master'
         uses: peaceiris/actions-gh-pages@v3
         with:

docs/Doxyfile

@@ -41,7 +41,7 @@ DOXYFILE_ENCODING      = UTF-8
 # project for which the documentation is generated. This name is used in the
 # title of most generated pages and in a few other places.
 
-PROJECT_NAME           = "Motis utl module"
+PROJECT_NAME           = "MOTIS utl module"
 
 # The PROJECT_NUMBER tag can be used to enter a project or revision number. This
 # could be handy for archiving the generated documentation or if some version

docs/README.md

@@ -12,6 +12,11 @@ Directly with `doxygen`:
     doxygen
 
 ## Generating Sphinx documentation
-From the root directory:
+From the root directory, with auto-reload:
 
     sphinx-autobuild docs docs/_build/html --open-browser
+
+Only generating the documentation:
+
+    cd docs
+    sphinx-build -M html . _build

docs/conf.py

@@ -6,9 +6,11 @@
 # -- Project information -----------------------------------------------------
 # https://www.sphinx-doc.org/en/master/usage/configuration.html#project-information
 
-project = 'Motis utl module'
-author = 'The Motis project developers'
-copyright = '2025, The Motis project developers'
+from pathlib import Path
+
+project = 'MOTIS utl module'
+author = 'The MOTIS project developers'
+copyright = '2025, The MOTIS project developers'
 html_show_copyright = False
 
 # -- General configuration ---------------------------------------------------

docs/index.rst

@@ -1,10 +1,10 @@
-Motis utl module documentation
+MOTIS utl module documentation
 ==============================
 
 MOTIS is an open-source software platform for efficient planning and routing in multi-modal transportation systems.
 GitHub main repository: https://github.com/motis-project/motis
 
-This is the documentation for the `utl` (utility) module.
+This is the documentation for the **utl** (utility) module.
 
 ..
    Table of contents
@@ -17,12 +17,35 @@ This is the documentation for the `utl` (utility) module.
 Logging
 -------
 
-Logs can be produced using the `log()` `struct`::
+The simplest way to produce log lines is to use the ``logF()`` macro::
 
-  utl::log() << "[" << utl::log::str["info"] << "]"        \
-             << "[" << utl::time() << "]"                  \
-             << "[" << FILE_NAME << ":" << __LINE__ << "]" \
-             << " Some message"
+  logF(info, "Simple message");
 
-.. doxygenstruct:: utl::log
-   :members:
+The following log levels are supported:
+
+debug
+  Messages that contain information only useful when debugging MOTIS
+
+info
+  Important information about a normal behavior of the program
+
+error
+  Details on an abnormal behavior of the application
+
+Advanced usage
+^^^^^^^^^^^^^^
+
+By default, ``logF()`` inserts the current filename & linenumber in the log line.
+However, you can use ``log()`` to specify your own **context** ::
+
+  log(info, "http.get.resource", "Details");
+
+You can also insert variables in the message by using ``{}`` and passing them as extra arguments::
+
+  logF(info, "String={} Int={}", "Hello", 42);
+
+API details
+^^^^^^^^^^^
+Under the hood, the ``log()`` & ``logF()`` macros use the ``utl::log()`` function:
+
+.. doxygenfunction:: utl::log

include/utl/logging.h

@@ -5,75 +5,84 @@
 #else
 
 #include <chrono>
-#include <cstring>
-#include <ctime>
+#include <iomanip>
 #include <iostream>
-#include <mutex>
+#include <sstream>
 #include <string>
 
-#ifdef _MSC_VER
-#define gmt(a, b) gmtime_s(b, a)
-#else
-#define gmt(a, b) gmtime_r(a, b)
-#endif
+#include "fmt/core.h"
+#include "fmt/ostream.h"
 
-#define FILE_NAME \
-  (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILE__)
+#define STRINGIFY(x) STRINGIFY_(x)
+#define STRINGIFY_(x) #x
 
-#define uLOG(lvl)                                          \
-  utl::log() << "[" << utl::log::str[lvl] << "]"           \
-             << "[" << utl::time() << "]"                  \
-             << "[" << FILE_NAME << ":" << __LINE__ << "]" \
-             << " "
+#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 {
 
-/**
-  Entrypoint for all Motis logs
-*/
-struct log {
-  log() = default;
-
-  log(log const&) = delete;
-  log& operator=(log const&) = delete;
-
-  log(log&&) = default;
-  log& operator=(log&&) = default;
+enum class log_level { debug, info, error };
 
-  template <typename T>
-  friend log&& operator<<(log&& l, T&& t) {
-    std::clog << std::forward<T&&>(t);
-    return std::move(l);
+constexpr char const* to_str(log_level const level) {
+  switch (level) {
+    case log_level::debug: return "debug";
+    case log_level::info: return "info";
+    case log_level::error: return "error";
   }
+  return "";
+}
 
-  ~log() { std::clog << std::endl; }
-
-  static constexpr const char* const str[]{"emrg", "alrt", "crit", "erro",
-                                           "warn", "note", "info", "debg"};
-};
+static log_level s_verbosity;
 
-enum log_level { emrg, alrt, crit, err, warn, notice, info, debug };
+inline std::string now() {
+  using clock = std::chrono::system_clock;
+  auto const now = clock::to_time_t(clock::now());
+  struct tm tmp {};
+#if _MSC_VER >= 1400
+  gmtime_s(&tmp, &now);
+#else
+  gmtime_r(&now, &tmp);
+#endif
 
-/**
-  Format a timestamp as an ISO 8601 string
-*/
-inline std::string time(time_t const t) {
-  char buf[sizeof "2011-10-08t07:07:09z-0430"];
-  struct tm result {};
-  gmt(&t, &result);
-  strftime(buf, sizeof buf, "%FT%TZ%z", &result);
-  return buf;
+  std::stringstream ss;
+  ss << std::put_time(&tmp, "%FT%TZ");
+  return ss.str();
 }
 
-/**
-  Format the current time as an ISO 8601 string
-*/
-inline std::string time() {
-  time_t now;
-  std::time(&now);
-  return time(now);
+/// 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)...)));
+  }
 }
 
 }  // namespace utl
 
-#endif
+/**
+ * Shorthand to invoke utl::log without specifying the namespace
+ */
+#define log(level, ctx, fmt_str, ...) \
+  utl::log(utl::log_level::##level, ctx, fmt_str, __VA_ARGS__)
+
+/**
+ * Invoke utl::log using the current C++ filename & line number as ctx
+ */
+#define logF(level, fmt_str, ...) \
+  log(level, FILE_AND_LINE_SHORT, fmt_str, __VA_ARGS__)
+
+#endif  // LOGGING_HEADER

include/utl/parallel_for.h

@@ -160,7 +160,7 @@ inline errors_t parallel_for(
       jobs.size(),
       [&](auto const idx) {
         if (idx % mod == 0) {
-          uLOG(info) << desc << " " << idx << "/" << jobs.size();
+          logF(info, "{} {}/{}", desc, idx, jobs.size());
         }
         func(jobs[idx]);
       },

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()} {
-  uLOG(info) << "[" << name_ << "] starting";
+  logF(info, "[{}] starting", name);
 }
 
 scoped_timer::~scoped_timer() {
@@ -15,8 +15,7 @@ scoped_timer::~scoped_timer() {
   double t =
       static_cast<double>(duration_cast<microseconds>(stop - start_).count()) /
       1000.0;
-  uLOG(info) << "[" << name_ << "] finished"
-             << " (" << t << "ms)";
+  logF(info, "[{}] finished ({}ms)", name_, t);
 }
 
 void scoped_timer::print(std::string_view const message) const {
@@ -25,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;
-  uLOG(info) << "[" << name_ << "] " << message << " (" << t << "ms)";
+  logF(info, "[{}] {} ({}ms)", name_, message, t);
 }
 
 manual_timer::manual_timer(std::string name)
     : name_{std::move(name)}, start_{std::chrono::steady_clock::now()} {
-  uLOG(info) << "[" << name_ << "] starting";
+  logF(info, "[{}] starting", name_);
 }
 
 void manual_timer::stop_and_print() const {
@@ -39,8 +38,7 @@ void manual_timer::stop_and_print() const {
   double t =
       static_cast<double>(duration_cast<microseconds>(stop - start_).count()) /
       1000.0;
-  uLOG(info) << "[" << name_ << "] finished"
-             << " (" << t << "ms)";
+  logF(info, "[{}] finished ({}ms)", name_, t);
 }
 
 void manual_timer::print(std::string_view const message) const {
@@ -49,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;
-  uLOG(info) << "[" << name_ << "] " << message << " (" << t << "ms)";
+  logF(info, "[{}] {} ({}ms)", name_, message, t);
 }
 
 }  // namespace utl

test/logging_test.cc

@@ -0,0 +1,30 @@
+#include <gmock/gmock.h>
+#include <gtest/gtest.h>
+
+#include "utl/logging.h"
+
+using ::testing::MatchesRegex;
+
+TEST(log, basic_usage) {
+  testing::internal::CaptureStderr();
+  logF(info, "Simple message");
+  EXPECT_THAT(
+      testing::internal::GetCapturedStderr(),
+      MatchesRegex(
+          ".+T.+Z \\[info\\] \\[logging_test.cc:10\\] Simple message\n"));
+};
+
+TEST(log, specifying_ctx) {
+  testing::internal::CaptureStderr();
+  log(info, "MyCtx", "Message");
+  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);
+  EXPECT_THAT(
+      testing::internal::GetCapturedStderr(),
+      MatchesRegex(".+T.+Z \\[info\\] \\[MyCtx\\] String=Hello Int=42\n"));
+};