Merge pull request #2037 from elBoberido/iox-1755-reintroduce-lazy-ev…

…aluation-for-the-logging iox-#1755 Reintroduce lazy evaluation for the logging
eclipse-iceoryx · Oct 24, 2023 · 36f0c44 · 36f0c44
2 parents 4fb0b5f + 2a5da9a
commit 36f0c44
Show file tree

Hide file tree

Showing 11 changed files with 267 additions and 222 deletions.
diff --git a/.github/workflows/lint_pull_request.yml b/.github/workflows/lint_pull_request.yml
@@ -21,10 +21,7 @@ jobs:
         id: changed_files
         uses: Ana06/[email protected]
       - name: diff scan, clang-tidy for all files which are in `.clang-tidy-diff-scans.txt`
-        run: |
-          for diff_file in ${{ steps.changed_files.outputs.added_modified }}; do
-            ./tools/scripts/clang_tidy_check.sh scan_list .clang-tidy-diff-scans.txt ${diff_file}
-          done
+        run: ./tools/scripts/clang_tidy_check.sh scan_list .clang-tidy-diff-scans.txt "${{ steps.changed_files.outputs.added_modified }}"
 
   check-for-todo:
     runs-on: ubuntu-latest
@@ -43,14 +40,14 @@ jobs:
     steps:
       - uses: actions/checkout@v3
 
+      - name: Calculate lychee cache key
+        run: echo "LYCHEE_CACHE_KEY=cache-lychee-all-branches-$(date +'%G-%V')" >> "$GITHUB_ENV" # %G = year; %V = week number
+
       - name: Restore lychee cache
         uses: actions/cache@v3
-        if: always()
         with:
           path: .lycheecache
-          key: cache-lychee-all-branches
-          # the cache will not be updated and therefore needs to be recreated after 7 days
-          retention-days: 7
+          key: ${{ env.LYCHEE_CACHE_KEY }}
 
       - name: Link Checker
         uses: lycheeverse/[email protected]

diff --git a/doc/design/logging.md b/doc/design/logging.md
@@ -95,22 +95,59 @@ by the `BaseLogger` template parameter and the latter by deriving from the logge
 
 ![logging with logstream](../website/images/logging_with_logstream.svg)
 
-#### Logging macro
+#### Logging macro with lazy evaluation
 
-The `IOX_LOG` macro is intended for general use. It has one parameter which
+The `IOX_LOG` macro is intended for general use. It has two parameters. The first one
 sets the log level and delegates `file`, `line` and `function` to the `IOX_LOG_INTERNAL`
 macro. The latter can be used in places like a custom `ASSERT` macro which already
-obtained the `file`, `line` and `function` parameter.
+obtained the `file`, `line` and `function` parameter. The second parameter contains
+the items to log and multiple items can be logged by using the '<<' operator.
 
-The `IOX_LOG_INTERNAL` uses the `iox::log::internal::SelectedLogStream` struct which is
-specialized for `LogLevel::OFF` to compile to a no-op when the logging data does not
-cause side effects. `IOX_LOG(INFO) << 42;` won't cause side effects but
-`IOX_LOG(INFO) << functionCall();` might have some.
+The buildup of the log message is only done when the condition to log the message
+is fulfilled. This is accomplished by a macro with an if-statement.
+
+```cpp
+#define LAZY(cond, expr) if (cond) { expr; }
+
+LAZY(x == 42, expensiveFunctionCall());
+```
+
+In the example above `expensiveFunctionCall` is only executed if `cond` is `true`.
+If `cond` is a compile time constant set to `false`, the whole statement is compiled
+to a no-op and optimized away.
+
+This is the log macro with lazy evaluation
+
+```cpp
+inline bool isLogLevelActive(LogLevel logLevel) noexcept
+{
+    return ((logLevel) <= MINIMAL_LOG_LEVEL)
+           && (IGNORE_ACTIVE_LOG_LEVEL || ((logLevel) <= iox::log::Logger::getLogLevel()));
+}
+
+#define IOX_LOG_INTERNAL(file, line, function, level, msg_stream)               \
+    if (iox::log::internal::isLogLevelActive(level))                            \
+    {                                                                           \
+        iox::log::LogStream(file, line, function, level).self() << msg_stream;  \
+    }                                                                           \
+    [] {} () // the empty lambda forces a semicolon on the caller side
+
+#define IOX_LOG(level, msg_stream)                                              \
+    IOX_LOG_INTERNAL(__FILE__, __LINE__, __FUNCTION__, iox::log::LogLevel::level, msg_stream)
+```
+
+With `MINIMAL_LOG_LEVEL` and `IGNORE_ACTIVE_LOG_LEVEL` being static `constexpr`
+constants the compiler will optimize this either to
+`if (false) { iox::log::LogStream(...) ... }` and finally completely away or
+`if ((level) <= iox::log::Logger::getLogLevel()) { iox::log::LogStream(...) ... }`.
+The minimal log level check is intended to fully optimize away a log statement
+and the ignore active log level check to always forward the log message to the
+logger, independent of the active log level.
 
 The `IOX_LOG_INTERNAL` calls `self()` on the `LogStream` instance to create an lvalue
 reference to the `LogStream` instance. This eases the implementation of logging
-support for custom types since `IOX_LOG(INFO) << myType;` would require to implement
-an overload with a rvalue `LogStream` reference but `IOX_LOG(INFO) << "#### " << myType;`
+support for custom types since `IOX_LOG(INFO, myType);` would require to implement
+an overload with a rvalue `LogStream` reference but `IOX_LOG(INFO, "#### " << myType);`
 requires a lvalue reference.
 
 #### Behavior before calling Logger::init
@@ -268,7 +305,7 @@ int main()
 {
     iox::log::Logger::init(iox::log::logLevelFromEnvOr(iox::log::LogLevel::DEBUG));
 
-    IOX_LOG(DEBUG) << "Hello World";
+    IOX_LOG(DEBUG, "Hello World");
 
     return 0;
 }
@@ -296,7 +333,7 @@ iox::log::LogStream& operator<<(iox::log::LogStream& stream, const MyType& m)
 int main()
 {
     MyType m;
-    IOX_LOG(INFO) << m;
+    IOX_LOG(INFO,  m);
 
     return 0;
 }
@@ -362,37 +399,23 @@ int main()
 {
     MyLogger::init();
 
-    IOX_LOG(FATAL) << "Whoops ... look, over there is a dead seagull flying!";
-    IOX_LOG(ERROR) << "Oh no!";
-    IOX_LOG(WARN) << "It didn't happen!";
-    IOX_LOG(INFO) << "All glory to the hypnotoad!";
-    IOX_LOG(DEBUG) << "I didn't do it!";
-    IOX_LOG(TRACE) << "Row row row your boat!";
+    IOX_LOG(FATAL, "Whoops ... look, over there is a dead seagull flying!");
+    IOX_LOG(ERROR, "Oh no!");
+    IOX_LOG(WARN, "It didn't happen!");
+    IOX_LOG(INFO, "All glory to the hypnotoad!");
+    IOX_LOG(DEBUG, "I didn't do it!");
+    IOX_LOG(TRACE, "Row row row your boat!");
 
     return 0;
 }
 ```
 
 ## Open issues
 
-### Lazy evaluation
-
-Lazy evaluation via the following macro clashes with static code analyzer which
-will generate warnings due to missing braces of the if-statement.
-
-```cpp
-#define LAZY() if (cond)
-
-LAZY() expensiveFunctionCall();
-```
-
-Lazy evaluation with stream based logging seems to be challenging. An alternative
-might be a variadic macro like `IOX_LOG(INFO, "Hello World");`
-
 ### Miscellaneous
 
 - do we need to change the log level after `Logger::init`
-- do we want a `IOX_LOG_IF(cond, level)` macro
+- do we want a `IOX_LOG_IF(cond, level, msg_stream)` macro
 - shall the `TestingLogger` register signals to catch `SIGTERM`, etc. and print the
   log messages when the signal is raised? It might be necessary to wait for the
   error handling refactoring before this can be done

diff --git a/doc/website/release-notes/iceoryx-unreleased.md b/doc/website/release-notes/iceoryx-unreleased.md
@@ -691,14 +691,14 @@
 
     auto& logger = iox::log::createLogger("MyComponent", "MyContext", iox::log::LogLevel::kInfo);
 
-    logger.LogInfo() << "Hello World";
+    logger.LogInfo() << "Hello World " << 42;
 
     // after
     #include "iox/logging.hpp"
 
     iox::log::Logger::init(iox::log::LogLevel::INFO);
 
-    IOX_LOG(INFO) << "Hello World";
+    IOX_LOG(INFO, "Hello World " << 42);
     ```
 
 31. Setting the default log level changed
@@ -771,7 +771,7 @@
     {
         void myFunc()
         {
-            LogInfo() << "Hello World";
+            LogInfo() << "Hello World " << 42;
         }
     }
 
@@ -784,21 +784,21 @@
     {
         void myFunc()
         {
-            IOX_LOG(INFO) << "Hello World";
+            IOX_LOG(INFO, "Hello World " << 42);
         }
     }
     ```
 
 34. Free function logger calls changed
 
-    | before         | after            |
-    |:--------------:|:----------------:|
-    | `LogFatal()`   | `IOX_LOG(FATAL)` |
-    | `LogError()`   | `IOX_LOG(ERROR)` |
-    | `LogWarn()`    | `IOX_LOG(WARN)`  |
-    | `LogInfo()`    | `IOX_LOG(INFO)`  |
-    | `LogDebug()`   | `IOX_LOG(DEBUG)` |
-    | `LogVerbose()` | `IOX_LOG(TRACE)` |
+    | before                | after                 |
+    |:---------------------:|:---------------------:|
+    | `LogFatal() << "x"`   | `IOX_LOG(FATAL, "x")` |
+    | `LogError() << "x"`   | `IOX_LOG(ERROR, "x")` |
+    | `LogWarn() << "x"`    | `IOX_LOG(WARN, "x")`  |
+    | `LogInfo() << "x"`    | `IOX_LOG(INFO, "x")`  |
+    | `LogDebug() << "x"`   | `IOX_LOG(DEBUG, "x")` |
+    | `LogVerbose() << "x"` | `IOX_LOG(TRACE, "x")` |
 
 35. Logger formatting changed
 
@@ -809,8 +809,8 @@
     LogInfo() << iox::log::RawBuffer(buf); // currently not supported
 
     // after
-    IOX_LOG(INFO) << iox::log::hex(42);
-    IOX_LOG(INFO) << iox::log::oct(42);
+    IOX_LOG(INFO, iox::log::hex(42));
+    IOX_LOG(INFO, iox::log::oct(42));
     ```
 
 36. Creating an instance of `LogStream` does not work anymore
@@ -827,15 +827,15 @@
     stream.Flush();
 
     // after
-    IOX_LOG(INFO) << [] (auto& stream) -> auto& {
+    IOX_LOG(INFO, [] (auto& stream) -> auto& {
         stream << "fibonacci: "
         for(auto fib : {1, 1, 2, 3, 5, 8})
         {
             stream << fib << ", ";
         }
         stream << "...";
         return stream;
-    };
+    });
     ```
 
 37. Testing of `LogStream::operator<<` overload for custom types changed

diff --git a/iceoryx_hoofs/include/iceoryx_hoofs/error_reporting/custom/default/error_reporting.inl b/iceoryx_hoofs/include/iceoryx_hoofs/error_reporting/custom/default/error_reporting.inl
@@ -53,7 +53,7 @@ namespace er
 // Custom panic with location
 [[noreturn]] inline void panic(const SourceLocation& location)
 {
-    IOX_ERROR_INTERNAL_LOG_PANIC(location) << "Panic";
+    IOX_ERROR_INTERNAL_LOG_PANIC(location, "Panic");
     panic();
 }
 
@@ -63,7 +63,7 @@ namespace er
 template <class Message>
 [[noreturn]] inline void panic(const SourceLocation& location, Message&& msg)
 {
-    IOX_ERROR_INTERNAL_LOG_PANIC(location) << "Panic " << msg;
+    IOX_ERROR_INTERNAL_LOG_PANIC(location, "Panic " << msg);
     panic();
 }
 
@@ -76,8 +76,9 @@ inline void report(const SourceLocation& location, Kind, const Error& error)
     auto moduleName = toModuleName(error);
     auto errorName = toErrorName(error);
 
-    IOX_ERROR_INTERNAL_LOG(location) << ": " << errorName << " (code " << code.value << ") in module " << moduleName
-                                     << " (id " << module.value << ")";
+    IOX_ERROR_INTERNAL_LOG(location,
+                           ": " << errorName << " (code " << code.value << ") in module " << moduleName << " (id "
+                                << module.value << ")");
     auto& h = ErrorHandler::get();
     h.onReportError(ErrorDescriptor(location, code, module));
 }
@@ -95,8 +96,9 @@ inline void report(const SourceLocation& location, iox::er::FatalKind kind, cons
     auto moduleName = toModuleName(error);
     auto errorName = toErrorName(error);
 
-    IOX_ERROR_INTERNAL_LOG_FATAL(location) << ": " << kind.name << " " << errorName << " (code " << code.value
-                                           << ") in module " << moduleName << " (id " << module.value << ")";
+    IOX_ERROR_INTERNAL_LOG_FATAL(location,
+                                 ": " << kind.name << " " << errorName << " (code " << code.value << ") in module "
+                                      << moduleName << " (id " << module.value << ")");
     auto& h = ErrorHandler::get();
     h.onReportError(ErrorDescriptor(location, code, module));
 }
@@ -106,7 +108,7 @@ inline void report(const SourceLocation& location, iox::er::PreconditionViolatio
 {
     auto code = toCode(error);
     auto module = toModule(error);
-    IOX_ERROR_INTERNAL_LOG_FATAL(location) << kind.name;
+    IOX_ERROR_INTERNAL_LOG_FATAL(location, kind.name);
     auto& h = ErrorHandler::get();
     h.onReportViolation(ErrorDescriptor(location, code, module));
 }
@@ -116,7 +118,7 @@ inline void report(const SourceLocation& location, iox::er::AssumptionViolationK
 {
     auto code = toCode(error);
     auto module = toModule(error);
-    IOX_ERROR_INTERNAL_LOG_FATAL(location) << kind.name;
+    IOX_ERROR_INTERNAL_LOG_FATAL(location, kind.name);
     auto& h = ErrorHandler::get();
     h.onReportViolation(ErrorDescriptor(location, code, module));
 }
@@ -127,7 +129,7 @@ report(const SourceLocation& location, iox::er::PreconditionViolationKind kind,
 {
     auto code = toCode(error);
     auto module = toModule(error);
-    IOX_ERROR_INTERNAL_LOG_FATAL(location) << kind.name << " " << std::forward<Message>(msg);
+    IOX_ERROR_INTERNAL_LOG_FATAL(location, kind.name << " " << std::forward<Message>(msg));
     auto& h = ErrorHandler::get();
     h.onReportViolation(ErrorDescriptor(location, code, module));
 }
@@ -138,7 +140,7 @@ report(const SourceLocation& location, iox::er::AssumptionViolationKind kind, co
 {
     auto code = toCode(error);
     auto module = toModule(error);
-    IOX_ERROR_INTERNAL_LOG_FATAL(location) << kind.name << " " << std::forward<Message>(msg);
+    IOX_ERROR_INTERNAL_LOG_FATAL(location, kind.name << " " << std::forward<Message>(msg));
     auto& h = ErrorHandler::get();
     h.onReportViolation(ErrorDescriptor(location, code, module));
 }

diff --git a/iceoryx_hoofs/include/iceoryx_hoofs/error_reporting/error_logging.hpp b/iceoryx_hoofs/include/iceoryx_hoofs/error_reporting/error_logging.hpp
@@ -25,19 +25,28 @@
 
 /// @brief Log the location of an error.
 /// @param location the location of the error
-#define IOX_ERROR_INTERNAL_LOG(location)                                                                               \
-    IOX_LOG_INTERNAL(location.file, location.line, location.function, iox::log::LogLevel::ERROR)                       \
-        << location.file << " line " << location.line
+/// @param msg_stream is the log message stream; multiple items can be logged by using the '<<' operator
+#define IOX_ERROR_INTERNAL_LOG(location, msg_stream)                                                                   \
+    IOX_LOG_INTERNAL(location.file,                                                                                    \
+                     location.line,                                                                                    \
+                     location.function,                                                                                \
+                     iox::log::LogLevel::ERROR,                                                                        \
+                     location.file << " line " << location.line << ": " << msg_stream)
 
 /// @brief Log the location of a fatal error.
 /// @param location the location of the error
-#define IOX_ERROR_INTERNAL_LOG_FATAL(location)                                                                         \
-    IOX_LOG_INTERNAL(location.file, location.line, location.function, iox::log::LogLevel::FATAL)                       \
-        << location.file << " line " << location.line << ": "
+/// @param msg_stream is the log message stream; multiple items can be logged by using the '<<' operator
+#define IOX_ERROR_INTERNAL_LOG_FATAL(location, msg_stream)                                                             \
+    IOX_LOG_INTERNAL(location.file,                                                                                    \
+                     location.line,                                                                                    \
+                     location.function,                                                                                \
+                     iox::log::LogLevel::FATAL,                                                                        \
+                     location.file << " line " << location.line << ": " << msg_stream)
 
 /// @brief Log a panic invocation.
 /// @param location the location of the panic invocation.
-#define IOX_ERROR_INTERNAL_LOG_PANIC(location) IOX_ERROR_INTERNAL_LOG_FATAL(location)
+/// @param msg_stream is the log message stream; multiple items can be logged by using the '<<' operator
+#define IOX_ERROR_INTERNAL_LOG_PANIC(location, msg_stream) IOX_ERROR_INTERNAL_LOG_FATAL(location, msg_stream)
 
 // NOLINTEND(cppcoreguidelines-macro-usage, bugprone-macro-parentheses)