From f3da88328e604c74ab31d722c92303d88632a328 Mon Sep 17 00:00:00 2001 From: Christian Eltzschig Date: Tue, 15 Oct 2024 15:40:48 +0200 Subject: [PATCH] [#4] Introduce developer guide with log documentation --- examples/rust/publish_subscribe/publisher.rs | 1 + .../cpp_doc_generator/developer_guide.rst | 7 + .../developer_guide_logging.rst | 303 ++++++++++++++++++ internal/cpp_doc_generator/index.rst | 2 + 4 files changed, 313 insertions(+) create mode 100644 internal/cpp_doc_generator/developer_guide.rst create mode 100644 internal/cpp_doc_generator/developer_guide_logging.rst diff --git a/examples/rust/publish_subscribe/publisher.rs b/examples/rust/publish_subscribe/publisher.rs index d8132e900..3b1c3e2b8 100644 --- a/examples/rust/publish_subscribe/publisher.rs +++ b/examples/rust/publish_subscribe/publisher.rs @@ -17,6 +17,7 @@ use iceoryx2::prelude::*; const CYCLE_TIME: Duration = Duration::from_secs(1); fn main() -> Result<(), Box> { + set_log_level(LogLevel::Trace); let node = NodeBuilder::new().create::()?; let service = node diff --git a/internal/cpp_doc_generator/developer_guide.rst b/internal/cpp_doc_generator/developer_guide.rst new file mode 100644 index 000000000..9b38f37d7 --- /dev/null +++ b/internal/cpp_doc_generator/developer_guide.rst @@ -0,0 +1,7 @@ +Developer Guide +=============== + +.. toctree:: + :maxdepth: 1 + + developer_guide_logging diff --git a/internal/cpp_doc_generator/developer_guide_logging.rst b/internal/cpp_doc_generator/developer_guide_logging.rst new file mode 100644 index 000000000..9a306ef5e --- /dev/null +++ b/internal/cpp_doc_generator/developer_guide_logging.rst @@ -0,0 +1,303 @@ +Logging +------- + +In this section, the log mechanisms of iceoryx2 are described in detail. We +begin by analyzing the structure of log messages and how they can be utilized +when debugging a process. Next, we describe the error-handling strategy, how to +log messages in general, and provide a table that outlines when to use each log +level. The final section explains how a user can implement a custom logger. + +Understanding The Log Output +^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +In iceoryx2, a log message typically consists of two parts: the origin and the +actual message. The origin refers to the debug output of the object that +emitted the log message. + +Including the origin is important because a backtrace, which points to a +specific line in the code, is often not enough. A typical setup might instantiate +many objects of the same type in different states, and a bug could be caused by +a subtle detail that affects a later statement. + +Therefore, the full object state is added as the origin. In the following example, +we see the log output of the `FileBuilder`, the class responsible for constructing +a `File` object. By including the object's state, we gain valuable details about +the file that was opened for reading. + +.. code-block:: + + +--------- monotonic counter + | +------ log level (T = Trace, D = Debug, I = Info, W = Warn, E = Error, F = Fatal) + | | +--- origin: the state (debug output) of the object that emitted the log + | | | message + | | | the actual log message ----------------+ + | | | | + | | | | + 0 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { | + len: 20, data: "config/iceoryx2.toml" } }, access_mode: Read, | + permission: Permission(448), has_ownership: false, owner: None, | + group: None, truncate_size: None, creation_mode: None } | + | opened ---------------------------------------------------------------+ + +How To Handle Errors +^^^^^^^^^^^^^^^^^^^^ + +In this section, we describe the error handling of internal iceoryx2 Rust code. +The language bindings may diverge from this approach when it does not align +with the idioms of the respective language. + +Non-Recoverable Errors +"""""""""""""""""""""" + +Non-recoverable errors describe scenarios where the program cannot continue and +would either encounter undefined behavior or crash in the next statement. For +example, this can occur when accessing an out-of-bounds array index or when a +corruption in the underlying OS is detected due to illegally modified managed +resources. + +In these cases, the only viable option is to terminate the program and provide +a detailed error message. + +Only the `fatal_panic!` macro should be used for such scenarios; **never** use +Rust's default `panic!` macro. While `fatal_panic!` utilizes `panic!` under the +hood, it also adds a final log message to the logger to inform the user of the +impending crash. + +.. code-block:: Rust + + // call from within an object + fn do_stuff(&self) { + // self must implement Debug + fatal_panic!(from self, "Something horrible has happened!"); + } + + // from a free function + fatal_panic!(from "some_context_here", "Something horrible has happened!"); + + // only fail when a function fails + fn do_stuff() -> Result<(), SomeError>; + fatal_panic!(from self, when do_stuff(), "Something horrible has happened!"); + +Recoverable Errors +"""""""""""""""""" + +Recoverable errors occur when something fails but with appropriate error +handling, the program can continue. For instance, attempting to open a file +without sufficient permissions would result in a recoverable error. In such +cases, the function would return an error wrapped inside a `Result`. + +In iceoryx2, we follow the rule that every `Err(..)` must be accompanied by a +debug log message, ensuring a complete error trace for easier debugging. + +To enforce the correct log level and message, iceoryx2 introduces the `fail!` +macro, which requires the origin, a log message, and optionally the error value. +**Never** use a combination of `return Err(..);` with a separate `debug!` log +message. + +.. code-block:: Rust + + // call from within an object + fn do_stuff(&self) -> Result<(), SomeError> { + // self must implement Debug + fail!(from self, + with SomeError::WhatEver, + "An error has occurred."); + } + + // from a free function + fn do_stuff() -> Result<(), SomeError> { + fail!(from "some_context_here", + with SomeError::WhatEver, + "An error has occurred."); + } + + // only fail when function fails, otherwise use value + fn call_me() -> Result; + fn do_stuff() -> Result<(), SomeError> { + let number = fail!(from "some_context_here", + when call_me(), + "An error has occurred."); + } + +A more complex example might involve a user trying to open a service, where the +following sequence of events happens under the hood: + +1. The static configuration file of the service is opened. + - Trace log message. +2. The deserialization fails because a field is missing. + - Debug log message informing the next layer about the issue. +3. The `ServiceBuilder` fails because the static details exist but cannot be read. + - Debug log message informing the user that the service appears to be in a corrupted state. + +This sequence allows us to trace exactly why the service is in a corrupted state, +specifically due to a deserialization failure. The following snippet demonstrates +a case where the file +`/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service` +of the service `My/Funk/ServiceName` cannot be deserialized because the field +`max_subscribers` is missing. + +Had we only relied on a stack trace pointing to the lines of code where the log +messages originated, we wouldn't have known which service was affected or which +underlying file had the issue. + +.. code-block:: + + 12 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { + len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb954857 + 59246ce1a2aa906.service" } }, access_mode: Read, + permission: Permission(448), has_ownership: false, owner: None, + group: None, truncate_size: None, creation_mode: None } + | opened + 13 [D] "Toml::deserialize" + | Failed to deserialize object (TOML parse error at line 5, column 1 + | + 5 | [messaging_pattern] + | ^^^^^^^^^^^^^^^^^^^ + missing field `max_subscribers` + ). + 14 [D] BuilderWithServiceType { service_config: StaticConfig { service_id: + ServiceId(RestrictedFileName { value: FixedSizeByteString<64> { len: + 40, data: "4eacadf2695a3f4b2eb95485759246ce1a2aa906" } }), + service_name: ServiceName { value: "My/Funk/ServiceName" }, .... + | Unable to deserialize the service config. Is the service corrupted? + +How To Log - What LogLevel To Use When +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +======== ========= ====================================================================================================== +LogLevel Recipient Description +======== ========= ====================================================================================================== +Trace Developer For interesting application events, e.g., whenever a resource like a file is created or destroyed. +Debug Developer Only used when a function that returns a `Result` encounters an error. +Info User For messages that are relevant to the user, such as "ready to perform tasks." +Warn User When functionality is restricted due to a recoverable error that has been mitigated. +Error User For severe failures where parts of the application cannot operate and no mitigation is possible. +Fatal User The last message before the application crashes. +======== ========= ====================================================================================================== + +Each log level has its corresponding macro and can be used in a similar manner +to the `fail!` and `fatal_panic!` macros. Below, we demonstrate the usage with +the `trace!` log macro. The `debug!`, `info!`, `warn!`, `error!`, and `fatal_panic!` +macros work in an identical way. + +.. code-block:: Rust + + // call from within an object + fn do_stuff(&self) { + // self must implement Debug + trace!(from self, "Something horrible has happened!"); + } + + // from a free function + trace!(from "some_context_here", "Something horrible has happened!"); + + // only log when a function fails + fn do_stuff() -> Result<(), SomeError>; + trace!(from self, when do_stuff(), "Something horrible has happened!"); + +Custom Logger +^^^^^^^^^^^^^ + +iceoryx2 allows users to set up their own custom logger. All approaches have two +things in common: the logger can only be set once, and once set, it will remain +the active logger until the process exits. + +Additionally, the logger must be set before the first log message is created. +If log messages have already been generated, the default logger is automatically +set and can no longer be changed. + +To integrate iceoryx2 with other Rust libraries, iceoryx2 provides support for +`log `_ and +`tracing `_. This can be enabled by using +either the `logger_log` or the `logger_tracing` feature flags. + +.. code-block:: Toml + + # Cargo.toml + [dependencies] + iceoryx2 = { version = "0.4", features = ["logger_log"] } + +Language: C +""""""""""" + +The C API provides the function `iox2_set_logger(iox2_log_callback logger)`, where +`iox2_log_callback` is a function pointer with the signature +`void (*iox2_log_callback)(enum iox2_log_level_e, const char* origin, const char* message)`. + +The following code snippet demonstrates how to implement a simple `printf` logger: + +.. code-block:: C + + #include "iceoryx2.h" + + void custom_logger(enum iox2_log_level_e, const char* origin, const char* message) { + printf("origin: %s, message: %s\n", origin, message); + } + + int main() { + if ( !iox2_set_logger(custom_logger) ) { + printf("Failed to set logger\n"); + } + } + +Language: C++ +""""""""""""" + +The C++ API provides the function `auto set_logger(Log& logger) -> bool`. Users +must provide a custom logger that implements the `Log` interface. This logger can +be attached, but it requires a static lifetime to ensure logging during the +application's shutdown phase. + +The following code snippet demonstrates how to implement a simple `std::cout` logger: + +.. code-block:: C++ + + #include "iox2/log.hpp" + + class CoutLogger : public iox2::Log { + public: + void log(LogLevel log_level, const char* origin, const char* message) override { + std::cout << "origin: " << origin << ", message: " << message << std::endl; + } + }; + + int main() { + static CoutLogger LOGGER; + + if ( !iox2::set_logger(&logger) ) { + std::cerr << "Failed to set logger" << std::endl; + } + } + +Language: Rust +"""""""""""""" + +The Rust API provides the function +`pub fn set_logger(value: &'static T) -> bool`. +A custom logger must implement the `Log` trait and requires a static lifetime to +ensure logging during the application's shutdown. + +The following code snippet demonstrates how to implement a simple `println!` logger: + +.. code-block:: Rust + use iceoryx2_bb_log::{set_logger, Log, LogLevel}; + use std::sync::LazyLock; + + #[derive(default)] + struct PrintLogger {} + + impl Log for PrintLogger { + fn log(&self, log_level: LogLevel, origin: std::fmt::Arguments, message: std::fmt::Arguments ) { + println!("log level: {:?}, origin: {}, message: {}", + log_level, origin.to_string(), message.to_string()); + } + } + + static LOGGER: LazyLock = LazyLock::new(|| PrintLogger::default()); + + fn main() { + if !set_logger(&*LOGGER) { + println!("Failed to set logger"); + } + } + diff --git a/internal/cpp_doc_generator/index.rst b/internal/cpp_doc_generator/index.rst index a329dd543..593c9f69d 100644 --- a/internal/cpp_doc_generator/index.rst +++ b/internal/cpp_doc_generator/index.rst @@ -10,6 +10,8 @@ Welcome to iceoryx2's C / C++ documentation! getting_started + developer_guide + iceoryx_hoofs_api iceoryx2_c_api