|
| 1 | +Logging |
| 2 | +------- |
| 3 | + |
| 4 | +In this section, the log mechanisms of iceoryx2 are described in detail. We |
| 5 | +begin by analyzing the structure of log messages and how they can be utilized |
| 6 | +when debugging a process. Next, we describe the error-handling strategy, how to |
| 7 | +log messages in general, and provide a table that outlines when to use each log |
| 8 | +level. The final section explains how a user can implement a custom logger. |
| 9 | + |
| 10 | +Understanding The Log Output |
| 11 | +^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 12 | + |
| 13 | +In iceoryx2, a log message typically consists of two parts: the origin and the |
| 14 | +actual message. The origin refers to the debug output of the object that |
| 15 | +emitted the log message. |
| 16 | + |
| 17 | +Including the origin is important because a backtrace, which points to a |
| 18 | +specific line in the code, is often not enough. A typical setup might instantiate |
| 19 | +many objects of the same type in different states, and a bug could be caused by |
| 20 | +a subtle detail that affects a later statement. |
| 21 | + |
| 22 | +Therefore, the full object state is added as the origin. In the following example, |
| 23 | +we see the log output of the `FileBuilder`, the class responsible for constructing |
| 24 | +a `File` object. By including the object's state, we gain valuable details about |
| 25 | +the file that was opened for reading. |
| 26 | + |
| 27 | +.. code-block:: |
| 28 | +
|
| 29 | + +--------- monotonic counter |
| 30 | + | +------ log level (T = Trace, D = Debug, I = Info, W = Warn, E = Error, F = Fatal) |
| 31 | + | | +--- origin: the state (debug output) of the object that emitted the log |
| 32 | + | | | message |
| 33 | + | | | the actual log message ----------------+ |
| 34 | + | | | | |
| 35 | + | | | | |
| 36 | + 0 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { | |
| 37 | + len: 20, data: "config/iceoryx2.toml" } }, access_mode: Read, | |
| 38 | + permission: Permission(448), has_ownership: false, owner: None, | |
| 39 | + group: None, truncate_size: None, creation_mode: None } | |
| 40 | + | opened ---------------------------------------------------------------+ |
| 41 | +
|
| 42 | +How To Handle Errors |
| 43 | +^^^^^^^^^^^^^^^^^^^^ |
| 44 | + |
| 45 | +In this section, we describe the error handling of internal iceoryx2 Rust code. |
| 46 | +The language bindings may diverge from this approach when it does not align |
| 47 | +with the idioms of the respective language. |
| 48 | + |
| 49 | +Non-Recoverable Errors |
| 50 | +"""""""""""""""""""""" |
| 51 | + |
| 52 | +Non-recoverable errors describe scenarios where the program cannot continue and |
| 53 | +would either encounter undefined behavior or crash in the next statement. For |
| 54 | +example, this can occur when accessing an out-of-bounds array index or when a |
| 55 | +corruption in the underlying OS is detected due to illegally modified managed |
| 56 | +resources. |
| 57 | + |
| 58 | +In these cases, the only viable option is to terminate the program and provide |
| 59 | +a detailed error message. |
| 60 | + |
| 61 | +Only the `fatal_panic!` macro should be used for such scenarios; **never** use |
| 62 | +Rust's default `panic!` macro. While `fatal_panic!` utilizes `panic!` under the |
| 63 | +hood, it also adds a final log message to the logger to inform the user of the |
| 64 | +impending crash. |
| 65 | + |
| 66 | +.. code-block:: Rust |
| 67 | +
|
| 68 | + // call from within an object |
| 69 | + fn do_stuff(&self) { |
| 70 | + // self must implement Debug |
| 71 | + fatal_panic!(from self, "Something horrible has happened!"); |
| 72 | + } |
| 73 | +
|
| 74 | + // from a free function |
| 75 | + fatal_panic!(from "some_context_here", "Something horrible has happened!"); |
| 76 | +
|
| 77 | + // only fail when a function fails |
| 78 | + fn do_stuff() -> Result<(), SomeError>; |
| 79 | + fatal_panic!(from self, when do_stuff(), "Something horrible has happened!"); |
| 80 | +
|
| 81 | +Recoverable Errors |
| 82 | +"""""""""""""""""" |
| 83 | + |
| 84 | +Recoverable errors occur when something fails but with appropriate error |
| 85 | +handling, the program can continue. For instance, attempting to open a file |
| 86 | +without sufficient permissions would result in a recoverable error. In such |
| 87 | +cases, the function would return an error wrapped inside a `Result`. |
| 88 | + |
| 89 | +In iceoryx2, we follow the rule that every `Err(..)` must be accompanied by a |
| 90 | +debug log message, ensuring a complete error trace for easier debugging. |
| 91 | + |
| 92 | +To enforce the correct log level and message, iceoryx2 introduces the `fail!` |
| 93 | +macro, which requires the origin, a log message, and optionally the error value. |
| 94 | +**Never** use a combination of `return Err(..);` with a separate `debug!` log |
| 95 | +message. |
| 96 | + |
| 97 | +.. code-block:: Rust |
| 98 | +
|
| 99 | + // call from within an object |
| 100 | + fn do_stuff(&self) -> Result<(), SomeError> { |
| 101 | + // self must implement Debug |
| 102 | + fail!(from self, |
| 103 | + with SomeError::WhatEver, |
| 104 | + "An error has occurred."); |
| 105 | + } |
| 106 | +
|
| 107 | + // from a free function |
| 108 | + fn do_stuff() -> Result<(), SomeError> { |
| 109 | + fail!(from "some_context_here", |
| 110 | + with SomeError::WhatEver, |
| 111 | + "An error has occurred."); |
| 112 | + } |
| 113 | +
|
| 114 | + // only fail when function fails, otherwise use value |
| 115 | + fn call_me() -> Result<i32, SomeError>; |
| 116 | + fn do_stuff() -> Result<(), SomeError> { |
| 117 | + let number = fail!(from "some_context_here", |
| 118 | + when call_me(), |
| 119 | + "An error has occurred."); |
| 120 | + } |
| 121 | +
|
| 122 | +A more complex example might involve a user trying to open a service, where the |
| 123 | +following sequence of events happens under the hood: |
| 124 | + |
| 125 | +1. The static configuration file of the service is opened. |
| 126 | + - Trace log message. |
| 127 | +2. The deserialization fails because a field is missing. |
| 128 | + - Debug log message informing the next layer about the issue. |
| 129 | +3. The `ServiceBuilder` fails because the static details exist but cannot be read. |
| 130 | + - Debug log message informing the user that the service appears to be in a corrupted state. |
| 131 | + |
| 132 | +This sequence allows us to trace exactly why the service is in a corrupted state, |
| 133 | +specifically due to a deserialization failure. The following snippet demonstrates |
| 134 | +a case where the file |
| 135 | +`/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb95485759246ce1a2aa906.service` |
| 136 | +of the service `My/Funk/ServiceName` cannot be deserialized because the field |
| 137 | +`max_subscribers` is missing. |
| 138 | + |
| 139 | +Had we only relied on a stack trace pointing to the lines of code where the log |
| 140 | +messages originated, we wouldn't have known which service was affected or which |
| 141 | +underlying file had the issue. |
| 142 | + |
| 143 | +.. code-block:: |
| 144 | +
|
| 145 | + 12 [T] FileBuilder { file_path: FilePath { value: FixedSizeByteString<255> { |
| 146 | + len: 76, data: "/tmp/iceoryx2/services/iox2_4eacadf2695a3f4b2eb954857 |
| 147 | + 59246ce1a2aa906.service" } }, access_mode: Read, |
| 148 | + permission: Permission(448), has_ownership: false, owner: None, |
| 149 | + group: None, truncate_size: None, creation_mode: None } |
| 150 | + | opened |
| 151 | + 13 [D] "Toml::deserialize" |
| 152 | + | Failed to deserialize object (TOML parse error at line 5, column 1 |
| 153 | + | |
| 154 | + 5 | [messaging_pattern] |
| 155 | + | ^^^^^^^^^^^^^^^^^^^ |
| 156 | + missing field `max_subscribers` |
| 157 | + ). |
| 158 | + 14 [D] BuilderWithServiceType { service_config: StaticConfig { service_id: |
| 159 | + ServiceId(RestrictedFileName { value: FixedSizeByteString<64> { len: |
| 160 | + 40, data: "4eacadf2695a3f4b2eb95485759246ce1a2aa906" } }), |
| 161 | + service_name: ServiceName { value: "My/Funk/ServiceName" }, .... |
| 162 | + | Unable to deserialize the service config. Is the service corrupted? |
| 163 | +
|
| 164 | +How To Log - What LogLevel To Use When |
| 165 | +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 166 | + |
| 167 | +======== ========= ====================================================================================================== |
| 168 | +LogLevel Recipient Description |
| 169 | +======== ========= ====================================================================================================== |
| 170 | +Trace Developer For interesting application events, e.g., whenever a resource like a file is created or destroyed. |
| 171 | +Debug Developer Only used when a function that returns a `Result` encounters an error. |
| 172 | +Info User For messages that are relevant to the user, such as "ready to perform tasks." |
| 173 | +Warn User When functionality is restricted due to a recoverable error that has been mitigated. |
| 174 | +Error User For severe failures where parts of the application cannot operate and no mitigation is possible. |
| 175 | +Fatal User The last message before the application crashes. |
| 176 | +======== ========= ====================================================================================================== |
| 177 | + |
| 178 | +Each log level has its corresponding macro and can be used in a similar manner |
| 179 | +to the `fail!` and `fatal_panic!` macros. Below, we demonstrate the usage with |
| 180 | +the `trace!` log macro. The `debug!`, `info!`, `warn!`, `error!`, and `fatal_panic!` |
| 181 | +macros work in an identical way. |
| 182 | + |
| 183 | +.. code-block:: Rust |
| 184 | +
|
| 185 | + // call from within an object |
| 186 | + fn do_stuff(&self) { |
| 187 | + // self must implement Debug |
| 188 | + trace!(from self, "Something horrible has happened!"); |
| 189 | + } |
| 190 | +
|
| 191 | + // from a free function |
| 192 | + trace!(from "some_context_here", "Something horrible has happened!"); |
| 193 | +
|
| 194 | + // only log when a function fails |
| 195 | + fn do_stuff() -> Result<(), SomeError>; |
| 196 | + trace!(from self, when do_stuff(), "Something horrible has happened!"); |
| 197 | +
|
| 198 | +Custom Logger |
| 199 | +^^^^^^^^^^^^^ |
| 200 | + |
| 201 | +iceoryx2 allows users to set up their own custom logger. All approaches have two |
| 202 | +things in common: the logger can only be set once, and once set, it will remain |
| 203 | +the active logger until the process exits. |
| 204 | + |
| 205 | +Additionally, the logger must be set before the first log message is created. |
| 206 | +If log messages have already been generated, the default logger is automatically |
| 207 | +set and can no longer be changed. |
| 208 | + |
| 209 | +To integrate iceoryx2 with other Rust libraries, iceoryx2 provides support for |
| 210 | +`log <https://crates.io/crates/log>`_ and |
| 211 | +`tracing <https://crates.io/crates/tracing>`_. This can be enabled by using |
| 212 | +either the `logger_log` or the `logger_tracing` feature flags. |
| 213 | + |
| 214 | +.. code-block:: Toml |
| 215 | +
|
| 216 | + # Cargo.toml |
| 217 | + [dependencies] |
| 218 | + iceoryx2 = { version = "0.4", features = ["logger_log"] } |
| 219 | +
|
| 220 | +Language: C |
| 221 | +""""""""""" |
| 222 | + |
| 223 | +The C API provides the function `iox2_set_logger(iox2_log_callback logger)`, where |
| 224 | +`iox2_log_callback` is a function pointer with the signature |
| 225 | +`void (*iox2_log_callback)(enum iox2_log_level_e, const char* origin, const char* message)`. |
| 226 | + |
| 227 | +The following code snippet demonstrates how to implement a simple `printf` logger: |
| 228 | + |
| 229 | +.. code-block:: C |
| 230 | +
|
| 231 | + #include "iceoryx2.h" |
| 232 | +
|
| 233 | + void custom_logger(enum iox2_log_level_e, const char* origin, const char* message) { |
| 234 | + printf("origin: %s, message: %s\n", origin, message); |
| 235 | + } |
| 236 | +
|
| 237 | + int main() { |
| 238 | + if ( !iox2_set_logger(custom_logger) ) { |
| 239 | + printf("Failed to set logger\n"); |
| 240 | + } |
| 241 | + } |
| 242 | +
|
| 243 | +Language: C++ |
| 244 | +""""""""""""" |
| 245 | + |
| 246 | +The C++ API provides the function `auto set_logger(Log& logger) -> bool`. Users |
| 247 | +must provide a custom logger that implements the `Log` interface. This logger can |
| 248 | +be attached, but it requires a static lifetime to ensure logging during the |
| 249 | +application's shutdown phase. |
| 250 | + |
| 251 | +The following code snippet demonstrates how to implement a simple `std::cout` logger: |
| 252 | + |
| 253 | +.. code-block:: C++ |
| 254 | + |
| 255 | + #include "iox2/log.hpp" |
| 256 | + |
| 257 | + class CoutLogger : public iox2::Log { |
| 258 | + public: |
| 259 | + void log(LogLevel log_level, const char* origin, const char* message) override { |
| 260 | + std::cout << "origin: " << origin << ", message: " << message << std::endl; |
| 261 | + } |
| 262 | + }; |
| 263 | + |
| 264 | + int main() { |
| 265 | + static CoutLogger LOGGER; |
| 266 | + |
| 267 | + if ( !iox2::set_logger(&logger) ) { |
| 268 | + std::cerr << "Failed to set logger" << std::endl; |
| 269 | + } |
| 270 | + } |
| 271 | + |
| 272 | +Language: Rust |
| 273 | +"""""""""""""" |
| 274 | + |
| 275 | +The Rust API provides the function |
| 276 | +`pub fn set_logger<T: Log + 'static>(value: &'static T) -> bool`. |
| 277 | +A custom logger must implement the `Log` trait and requires a static lifetime to |
| 278 | +ensure logging during the application's shutdown. |
| 279 | + |
| 280 | +The following code snippet demonstrates how to implement a simple `println!` logger: |
| 281 | + |
| 282 | +.. code-block:: Rust |
| 283 | +
|
| 284 | + use iceoryx2_bb_log::{set_logger, Log, LogLevel}; |
| 285 | + use std::sync::LazyLock; |
| 286 | +
|
| 287 | + #[derive(default)] |
| 288 | + struct PrintLogger {} |
| 289 | +
|
| 290 | + impl Log for PrintLogger { |
| 291 | + fn log(&self, log_level: LogLevel, origin: std::fmt::Arguments, message: std::fmt::Arguments ) { |
| 292 | + println!("log level: {:?}, origin: {}, message: {}", |
| 293 | + log_level, origin.to_string(), message.to_string()); |
| 294 | + } |
| 295 | + } |
| 296 | +
|
| 297 | + static LOGGER: LazyLock<PrintLogger> = LazyLock::new(|| PrintLogger::default()); |
| 298 | +
|
| 299 | + fn main() { |
| 300 | + if !set_logger(&*LOGGER) { |
| 301 | + println!("Failed to set logger"); |
| 302 | + } |
| 303 | + } |
| 304 | +
|
0 commit comments