| 1 | // Render with Asciidoctor |
| 2 | |
| 3 | = Babeltrace contributor's guide |
| 4 | Jérémie Galarneau, Philippe Proulx |
| 5 | v0.2, 19 June 2019 |
| 6 | :toc: |
| 7 | :toclevels: 5 |
| 8 | |
| 9 | |
| 10 | This is a partial contributor's guide for the |
| 11 | http://diamon.org/babeltrace[Babeltrace] project. If you have any |
| 12 | questions that are not answered by this guide, please post them on |
| 13 | https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev[Babeltrace's |
| 14 | mailing list]. |
| 15 | |
| 16 | |
| 17 | == Babeltrace library |
| 18 | |
| 19 | === Object reference counting and lifetime |
| 20 | |
| 21 | This section covers the rationale behind the design of Babeltrace's |
| 22 | object lifetime management. This applies to the Babeltrace library, as |
| 23 | well as to the CTF writer library (although the public reference |
| 24 | counting functions are not named the same way). |
| 25 | |
| 26 | Starting from Babeltrace 2.0, all publicly exposed objects inherit a |
| 27 | common base: `bt_object`. This base provides a number of facilities to |
| 28 | all objects, chief amongst which are lifetime management functions. |
| 29 | |
| 30 | The lifetime of some public objects is managed by reference counting. In |
| 31 | this case, the API offers the `+bt_*_get_ref()+` and `+bt_*_put_ref()+` |
| 32 | functions which respectively increment and decrement an object's |
| 33 | reference count. |
| 34 | |
| 35 | As far as lifetime management in concerned, Babeltrace makes a clear |
| 36 | distinction between regular objects, which have a single parent, and |
| 37 | root objects, which don't. |
| 38 | |
| 39 | |
| 40 | ==== The problem |
| 41 | |
| 42 | Let us consider a problematic case to illustrate the need for this |
| 43 | distinction. |
| 44 | |
| 45 | A user of the Babeltrace library creates a trace class, which _has_ a |
| 46 | stream class (the class of a stream) and that stream class, in turn, |
| 47 | _has_ an event class (the class of an event). |
| 48 | |
| 49 | Nothing prevents this user from releasing his reference on any one of |
| 50 | these objects in any order. However, all objects in the |
| 51 | __trace--stream class--event class__ hierarchy can be retrieved |
| 52 | from any other. |
| 53 | |
| 54 | For instance, the user could discard his reference on both the event |
| 55 | class and the stream class, only keeping a reference on the trace class. |
| 56 | From this trace class reference, stream classes can be enumerated, |
| 57 | providing the user with a new reference to the stream class he discarded |
| 58 | earlier. Event classes can also be enumerated from stream classes, |
| 59 | providing the user with references to the individual event classes. |
| 60 | |
| 61 | Conversely, the user could also hold a reference to an event class and |
| 62 | retrieve its parent stream class. The trace class, in turn, can then be |
| 63 | retrieved from the stream class. |
| 64 | |
| 65 | This example illustrates what could be interpreted as a circular |
| 66 | reference dependency existing between these objects. Of course, if the |
| 67 | objects in such a scenario were to hold references to each other (in |
| 68 | both directions), we would be in presence of a circular ownership |
| 69 | resulting in a leak of both objects as their reference counts would |
| 70 | never reach zero. |
| 71 | |
| 72 | Nonetheless, the API must offer the guarantee that holding a node to any |
| 73 | node of the graph keeps all other reachable nodes alive. |
| 74 | |
| 75 | |
| 76 | ==== The solution |
| 77 | |
| 78 | The scheme employed in Babeltrace to break this cycle consists in the |
| 79 | "children" holding _reverse component references_ to their parents. That |
| 80 | is, in the context of the trace IR, that event classes hold a reference |
| 81 | to their parent stream class and stream classes hold a reference to |
| 82 | their parent trace class. |
| 83 | |
| 84 | On the other hand, parents hold _claiming aggregation references_ to |
| 85 | their children. A claiming aggregation reference means that the object |
| 86 | being referenced should not be deleted as long as the reference still |
| 87 | exists. In this respect, it can be said that parents truly hold the |
| 88 | ownership of their children, since they control their lifetime. |
| 89 | Conversely, the reference counting mechanism is leveraged by children to |
| 90 | notify parents that no other child indirectly exposes the parent. |
| 91 | |
| 92 | When a parented object's reference count reaches zero, it invokes |
| 93 | `+bt_*_put_ref()+` on its parent and does _not_ free itself. However, |
| 94 | from that point, the object depends on its parent to signal the moment |
| 95 | when it can be safely reclaimed. |
| 96 | |
| 97 | The invocation of `+bt_*_put_ref()+` by the last children holding a |
| 98 | reference to its parent might trigger a cascade of `+bt_*_put_ref()+` |
| 99 | from child to parent. Eventually, a **root** object is reached. At that |
| 100 | point, if this orphaned object's reference count reaches zero, the |
| 101 | object invokes the destructor method defined by everyone of its children |
| 102 | as part of their base `struct bt_object`. The key point here is that the |
| 103 | cascade of destructor will necessarily originate from the root and |
| 104 | propagate in preorder to the children. These children will propagate the |
| 105 | destruction to their own children before reclaiming their own memory. |
| 106 | This ensures that a node's pointer to its parent is _always_ valid since |
| 107 | the parent has the responsibility of tearing-down their children before |
| 108 | cleaning themselves up. |
| 109 | |
| 110 | Assuming a reference to an object is _acquired_ by calling |
| 111 | `+bt_*_get_ref()+` while its reference count is zero, the object |
| 112 | acquires, in turn, a reference on its parent using `+bt_*_get_ref()+`. |
| 113 | At that point, the child can be thought of as having converted its weak |
| 114 | reference to its parent into a regular reference. That is why this |
| 115 | reference is referred to as a _claiming_ aggregation reference. |
| 116 | |
| 117 | |
| 118 | ==== Caveats |
| 119 | |
| 120 | This scheme imposes a number of strict rules defining the relation |
| 121 | between objects: |
| 122 | |
| 123 | * Objects may only have one parent. |
| 124 | * Objects, beside the root, are only retrievable from their direct |
| 125 | parent or children. |
| 126 | |
| 127 | |
| 128 | ==== Example |
| 129 | |
| 130 | The initial situation is rather simple: **User{nbsp}A** is holding a |
| 131 | reference to a trace class, **TC1**. As per the rules previously |
| 132 | enounced, stream classes **SC1** and **SC2** don't hold a reference to |
| 133 | **TC1** since their own reference counts are zero. The same holds true |
| 134 | for **EC1**, **EC2** and **EC3** with respect to **SC1** and **SC2**. |
| 135 | |
| 136 | image::doc/contributing-images/bt-ref01.png[] |
| 137 | |
| 138 | In this second step, we can see that **User{nbsp}A** has acquired a |
| 139 | reference on **SC2** through the trace class, **TC1**. |
| 140 | |
| 141 | The stream class's reference count transitions from zero to one, |
| 142 | triggering the acquisition of a strong reference on **TC1** from |
| 143 | **SC2**. |
| 144 | |
| 145 | Hence, at this point, the trace class's ownership is shared by |
| 146 | **User{nbsp}A** and **SC2**. |
| 147 | |
| 148 | image::doc/contributing-images/bt-ref02.png[] |
| 149 | |
| 150 | Next, **User{nbsp}A** acquires a reference on the **EC3** event class |
| 151 | through its parent stream class, **SC2**. Again, the transition of an |
| 152 | object's reference count from 0 to 1 triggers the acquisition of a |
| 153 | reference on its parent. |
| 154 | |
| 155 | Note that SC2's reference count was incremented to 2. The trace class's |
| 156 | reference count remains unchanged. |
| 157 | |
| 158 | image::doc/contributing-images/bt-ref03.png[] |
| 159 | |
| 160 | **User{nbsp}A** decides to drop its reference on **SC2**. **SC2**'s |
| 161 | reference count returns back to 1, everything else remaining unchanged. |
| 162 | |
| 163 | image::doc/contributing-images/bt-ref04.png[] |
| 164 | |
| 165 | **User{nbsp}A** can then decide to drop its reference on the trace |
| 166 | class. This results in a reversal of the initial situation: |
| 167 | **User{nbsp}A** now owns an event, **EC3**, which is keeping everything |
| 168 | else alive and reachable. |
| 169 | |
| 170 | image::doc/contributing-images/bt-ref05.png[] |
| 171 | |
| 172 | If another object, **User{nbsp}B**, enters the picture and acquires a |
| 173 | reference on the **SC1** stream class, we see that **SC1**'s reference |
| 174 | count transitioned from 0 to 1, triggering the acquisition of a |
| 175 | reference on **TC1**. |
| 176 | |
| 177 | image::doc/contributing-images/bt-ref06.png[] |
| 178 | |
| 179 | **User{nbsp}B** hands off a reference to **EC1**, acquired through |
| 180 | **SC1**, to another object, **User{nbsp}C**. The acquisition of a |
| 181 | reference on **EC1**, which transitions from 0 to 1, triggers the |
| 182 | acquisition of a reference on its parent, **SC1**. |
| 183 | |
| 184 | image::doc/contributing-images/bt-ref07.png[] |
| 185 | |
| 186 | At some point, **User{nbsp}A** releases its reference on **EC3**. Since |
| 187 | **EC3**'s reference count transitions to zero, it releases its reference |
| 188 | on **SC2**. **SC2**'s reference count, in turn, reaches zero and it |
| 189 | releases its reference to **TC1**. |
| 190 | |
| 191 | **TC1**'s reference count is now 1 and no further action is taken. |
| 192 | |
| 193 | image::doc/contributing-images/bt-ref08.png[] |
| 194 | |
| 195 | **User{nbsp}B** releases its reference on **SC1**. **User{nbsp}C** |
| 196 | becomes the sole owner of the whole hierarchy through his ownership of |
| 197 | **EC1**. |
| 198 | |
| 199 | image::doc/contributing-images/bt-ref09.png[] |
| 200 | |
| 201 | Finally, **User{nbsp}C** releases his ownership of **EC1**, triggering |
| 202 | the release of the whole hierarchy. Let's walk through the reclamation |
| 203 | of the whole graph. |
| 204 | |
| 205 | Mirroring what happened when **User{nbsp}A** released its last reference |
| 206 | on **EC3**, the release of **EC1** by **User{nbsp}C** causes its |
| 207 | reference count to fall to zero. |
| 208 | |
| 209 | This transition to zero causes **EC1** to release its reference on |
| 210 | **SC1**. **SC1**'s reference count reaching zero causes it to release |
| 211 | its reference on **TC1**. |
| 212 | |
| 213 | image::doc/contributing-images/bt-ref10.png[] |
| 214 | |
| 215 | Since the reference count of **TC1**, a root object, has reached zero, |
| 216 | it invokes the destructor method on its children. This method is |
| 217 | recursive and causes the stream classes to call the destructor method on |
| 218 | their event classes. |
| 219 | |
| 220 | The event classes are reached and, having no children of their own, are |
| 221 | reclaimed. |
| 222 | |
| 223 | image::doc/contributing-images/bt-ref11.png[] |
| 224 | |
| 225 | The stream classes having destroyed their children, are then reclaimed |
| 226 | by the trace class. |
| 227 | |
| 228 | image::doc/contributing-images/bt-ref12.png[] |
| 229 | |
| 230 | Finally, the stream classes having been reclaimed, **TC1** is reclaimed. |
| 231 | |
| 232 | image::doc/contributing-images/bt-ref13.png[] |
| 233 | |
| 234 | |
| 235 | == Logging |
| 236 | |
| 237 | Logging is a great instrument for a developer to be able to collect |
| 238 | information about a running software. |
| 239 | |
| 240 | Babeltrace is a complex software with many layers. When a Babeltrace |
| 241 | graph fails to run, what caused the failure? It could be caused by any |
| 242 | component, any message iterator, and any deeply nested validation of a |
| 243 | CTF IR object (within the `ctf` plugin), for example. With the |
| 244 | appropriate logging statements manually placed in the source code, we |
| 245 | can find the cause of a bug faster. |
| 246 | |
| 247 | While <<choose-a-log-level,care must be taken>> when placing _DEBUG_ to |
| 248 | _FATAL_ logging statements, you should liberally instrument your |
| 249 | Babeltrace module with _TRACE_ logging statements to help future you |
| 250 | and other developers understand what's happening at run time. |
| 251 | |
| 252 | |
| 253 | === Logging API |
| 254 | |
| 255 | The Babeltrace logging API is internal: it is not exposed to the users |
| 256 | of the library; only to their developers. The only thing that a library |
| 257 | user can control is the current log level of the library itself with |
| 258 | `bt_logging_set_global_level()` and the initial library's log level with |
| 259 | the `LIBBABELTRACE2_INIT_LOG_LEVEL` environment variable. |
| 260 | |
| 261 | This API is based on https://github.com/wonder-mice/zf_log[zf_log], a |
| 262 | lightweight, yet featureful, MIT-licensed core logging library for C and |
| 263 | pass:[C++]. The zf_log source files were modified to have the `BT_` and |
| 264 | `bt_` prefixes, and other small changes, like color support and using |
| 265 | the project's `BT_DEBUG_MODE` definition instead of the standard |
| 266 | `NDEBUG`. |
| 267 | |
| 268 | The logging functions are implemented in the logging convenience |
| 269 | library (`src/logging` directory). |
| 270 | |
| 271 | |
| 272 | [[logging-headers]] |
| 273 | ==== Headers |
| 274 | |
| 275 | The logging API headers are: |
| 276 | |
| 277 | `<babeltrace2/logging.h>`:: |
| 278 | Public header which a library user can use to set and get |
| 279 | libbabeltrace2's current log level. |
| 280 | |
| 281 | `"logging/log.h"`:: |
| 282 | Internal, generic logging API which you can use in any Babeltrace |
| 283 | module. This is the translation of `zf_log.h`. |
| 284 | + |
| 285 | This header offers the <<gen-logging-statements,generic logging |
| 286 | statement macros>>. |
| 287 | |
| 288 | `"lib/logging.h"`:: |
| 289 | Specific internal header to use within the library. |
| 290 | + |
| 291 | This header defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide |
| 292 | hidden symbol which is the library's current log level before including |
| 293 | `"logging/log.h"`. |
| 294 | + |
| 295 | This header offers the <<lib-logging-statements,library-specific logging |
| 296 | statement macros>>. |
| 297 | |
| 298 | `"logging/comp-logging.h"`:: |
| 299 | Specific internal header to use within a component class. |
| 300 | + |
| 301 | This header offers the <<comp-logging-statements,component-specific |
| 302 | logging statement macros>>. |
| 303 | |
| 304 | |
| 305 | [[log-levels]] |
| 306 | ==== Log levels |
| 307 | |
| 308 | The internal logging API offers the following log levels, in ascending |
| 309 | order of severity: |
| 310 | |
| 311 | [options="header,autowidth",cols="4"] |
| 312 | |=== |
| 313 | |Log level name |
| 314 | |Log level short name |
| 315 | |Internal API enumerator |
| 316 | |Public API enumerator |
| 317 | |
| 318 | |_TRACE_ |
| 319 | |`T` |
| 320 | |`BT_LOG_TRACE` |
| 321 | |`BT_LOGGING_LEVEL_TRACE` |
| 322 | |
| 323 | |_DEBUG_ |
| 324 | |`D` |
| 325 | |`BT_LOG_DEBUG` |
| 326 | |`BT_LOGGING_LEVEL_DEBUG` |
| 327 | |
| 328 | |_INFO_ |
| 329 | |`I` |
| 330 | |`BT_LOG_INFO` |
| 331 | |`BT_LOGGING_LEVEL_INFO` |
| 332 | |
| 333 | |_WARNING_ |
| 334 | |`W` |
| 335 | |`BT_LOG_WARNING` |
| 336 | |`BT_LOGGING_LEVEL_WARNING` |
| 337 | |
| 338 | |_ERROR_ |
| 339 | |`E` |
| 340 | |`BT_LOG_ERROR` |
| 341 | |`BT_LOGGING_LEVEL_ERROR` |
| 342 | |
| 343 | |_FATAL_ |
| 344 | |`F` |
| 345 | |`BT_LOG_FATAL` |
| 346 | |`BT_LOGGING_LEVEL_FATAL` |
| 347 | |
| 348 | |_NONE_ |
| 349 | |`N` |
| 350 | |`BT_LOG_NONE` |
| 351 | |`BT_LOGGING_LEVEL_NONE` |
| 352 | |=== |
| 353 | |
| 354 | The short name is accepted by the log level environment variables and by |
| 355 | the CLI's `--log-level` options. |
| 356 | |
| 357 | See <<choose-a-log-level,how to decide which one to use>> below. |
| 358 | |
| 359 | There are two important log level expressions: |
| 360 | |
| 361 | [[build-time-log-level]]Build-time, minimal log level:: |
| 362 | The minimal log level, or build-time log level, is set at build time |
| 363 | and determines the minimal log level of the logging statements which |
| 364 | can be executed. This applies to all the modules (CLI, library, |
| 365 | plugins, bindings, etc.). |
| 366 | + |
| 367 | All the logging statements with a level below this level are **not built |
| 368 | at all**. All the logging statements with a level equal to or greater |
| 369 | than this level _can_ be executed, depending on the |
| 370 | <<run-time-log-level,run-time log level>>. |
| 371 | + |
| 372 | You can set this level at configuration time with the |
| 373 | `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example: |
| 374 | + |
| 375 | -- |
| 376 | ---- |
| 377 | $ BABELTRACE_MINIMAL_LOG_LEVEL=INFO ./configure |
| 378 | ---- |
| 379 | -- |
| 380 | + |
| 381 | The default build-time log level is `DEBUG`. For optimal performance, |
| 382 | set it to `INFO`, which effectively disables all fast path logging in |
| 383 | all the Babeltrace modules. You can't set it to `WARNING`, `ERROR`, |
| 384 | `FATAL`, or `NONE` because the impact on performance is minuscule |
| 385 | starting from the _INFO_ log level anyway and we want any Babeltrace |
| 386 | build to always be able to print _INFO_-level logs. |
| 387 | + |
| 388 | The library's public API provides `bt_logging_get_minimal_level()` to |
| 389 | get the configured minimal log level. |
| 390 | |
| 391 | [[run-time-log-level]]Run-time, dynamic log level:: |
| 392 | The dynamic log level is set at run time and determines the current, |
| 393 | _active_ log level. All the logging statements with a level below |
| 394 | this level are not executed, **but they still evaluate the |
| 395 | condition**. All the logging statements with a level equal to or |
| 396 | greater than this level are executed, provided that their level is |
| 397 | also <<build-time-log-level,enabled at build time>>. |
| 398 | + |
| 399 | `zf_log` has a concept of a global run-time log level which uses the |
| 400 | `_bt_log_global_output_lvl` symbol. In practice, we never use this |
| 401 | symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined to a |
| 402 | module-wise expression before including `"logging/log.h"`. |
| 403 | + |
| 404 | In the library, `"lib/logging.h"` defines its own |
| 405 | `BT_LOG_OUTPUT_LEVEL` to the library's log level symbol before it |
| 406 | includes `"logging/log.h"` itself. |
| 407 | + |
| 408 | In libbabeltrace2, the user can set the current run-time log level with |
| 409 | the `bt_logging_set_global_level()` function, for example: |
| 410 | + |
| 411 | -- |
| 412 | [source,c] |
| 413 | ---- |
| 414 | bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO); |
| 415 | ---- |
| 416 | -- |
| 417 | + |
| 418 | The library's initial run-time log level is defined by the |
| 419 | `LIBBABELTRACE2_INIT_LOG_LEVEL` environment variable, or set to _NONE_ |
| 420 | if this environment variable is undefined. |
| 421 | + |
| 422 | Other modules have their own way of setting their run-time log level. |
| 423 | + |
| 424 | For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL` environment |
| 425 | variable, as well as its global `--log-level` option: |
| 426 | + |
| 427 | ---- |
| 428 | $ babeltrace2 --log-level=I ... |
| 429 | ---- |
| 430 | + |
| 431 | The components use their own log level (as returned by |
| 432 | `bt_component_get_logging_level()`). With the CLI, you can set a |
| 433 | specific component's log level with its own, position-dependent |
| 434 | `--log-level` option: |
| 435 | + |
| 436 | ---- |
| 437 | $ babeltrace2 /path/to/trace -c sink.ctf.fs --log-level=D |
| 438 | ---- |
| 439 | + |
| 440 | Code which is common to the whole project, for example `src/common` |
| 441 | and `src/compat`, use function parameters to get its run-time log |
| 442 | level, for example: |
| 443 | + |
| 444 | [source,c] |
| 445 | ---- |
| 446 | BT_HIDDEN |
| 447 | char *bt_common_get_home_plugin_path(int log_level); |
| 448 | ---- |
| 449 | + |
| 450 | Typically, when a logging-enabled module calls such a function, it |
| 451 | passes its own log level expression directly (`BT_LOG_OUTPUT_LEVEL`): |
| 452 | + |
| 453 | [source,c] |
| 454 | ---- |
| 455 | path = bt_common_get_home_plugin_path(BT_LOG_OUTPUT_LEVEL); |
| 456 | ---- |
| 457 | + |
| 458 | Otherwise, just pass `BT_LOG_NONE`: |
| 459 | + |
| 460 | ---- |
| 461 | path = bt_common_get_home_plugin_path(BT_LOG_NONE); |
| 462 | ---- |
| 463 | |
| 464 | |
| 465 | [[gen-logging-statements]] |
| 466 | ==== Generic logging statement macros |
| 467 | |
| 468 | The Babeltrace logging statement macros work just like `printf()` |
| 469 | (except the `+BT_LOG*_STR()+` ones) and contain their <<log-levels,log |
| 470 | level>> (short name) in their name. |
| 471 | |
| 472 | Each of the following macros evaluate the |
| 473 | <<build-time-log-level,build-time log level>> definition and |
| 474 | <<run-time-log-level,run-time log level>> expression (as defined by |
| 475 | `BT_LOG_OUTPUT_LEVEL`) to log conditionally. |
| 476 | |
| 477 | See <<logging-instrument-c-file-gen,Instrument a C source file |
| 478 | (generic)>> and <<logging-instrument-h-file-gen,Instrument a C header |
| 479 | file (generic)>> to learn how to be able to use the following macros. |
| 480 | |
| 481 | `+BT_LOGT("format string", ...)+`:: |
| 482 | Generic trace logging statement. |
| 483 | |
| 484 | `+BT_LOGD("format string", ...)+`:: |
| 485 | Generic debug logging statement. |
| 486 | |
| 487 | `+BT_LOGI("format string", ...)+`:: |
| 488 | Generic info logging statement. |
| 489 | |
| 490 | `+BT_LOGW("format string", ...)+`:: |
| 491 | Generic warning logging statement. |
| 492 | |
| 493 | `+BT_LOGE("format string", ...)+`:: |
| 494 | Generic error logging statement. |
| 495 | |
| 496 | `+BT_LOGF("format string", ...)+`:: |
| 497 | Generic fatal logging statement. |
| 498 | |
| 499 | `+BT_LOGT_STR("preformatted string")+`:: |
| 500 | Generic preformatted string trace logging statement. |
| 501 | |
| 502 | `+BT_LOGD_STR("preformatted string")+`:: |
| 503 | Generic preformatted string debug logging statement. |
| 504 | |
| 505 | `+BT_LOGI_STR("preformatted string")+`:: |
| 506 | Generic preformatted string info logging statement. |
| 507 | |
| 508 | `+BT_LOGW_STR("preformatted string")+`:: |
| 509 | Generic preformatted string warning logging statement. |
| 510 | |
| 511 | `+BT_LOGE_STR("preformatted string")+`:: |
| 512 | Generic preformatted string error logging statement. |
| 513 | |
| 514 | `+BT_LOGF_STR("preformatted string")+`:: |
| 515 | Generic preformatted string fatal logging statement. |
| 516 | |
| 517 | `+BT_LOGT_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 518 | Generic memory trace logging statement. |
| 519 | |
| 520 | `+BT_LOGD_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 521 | Generic memory debug logging statement. |
| 522 | |
| 523 | `+BT_LOGI_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 524 | Generic memory info logging statement. |
| 525 | |
| 526 | `+BT_LOGW_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 527 | Generic memory warning logging statement. |
| 528 | |
| 529 | `+BT_LOGE_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 530 | Generic memory error logging statement. |
| 531 | |
| 532 | `+BT_LOGF_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 533 | Generic memory fatal logging statement. |
| 534 | |
| 535 | `+BT_LOGT_ERRNO("initial message", "format string", ...)+`:: |
| 536 | Generic `errno` string trace logging statement. |
| 537 | |
| 538 | `+BT_LOGD_ERRNO("initial message", "format string", ...)+`:: |
| 539 | Generic `errno` string debug logging statement. |
| 540 | |
| 541 | `+BT_LOGI_ERRNO("initial message", "format string", ...)+`:: |
| 542 | Generic `errno` string info logging statement. |
| 543 | |
| 544 | `+BT_LOGW_ERRNO("initial message", "format string", ...)+`:: |
| 545 | Generic `errno` string warning logging statement. |
| 546 | |
| 547 | `+BT_LOGE_ERRNO("initial message", "format string", ...)+`:: |
| 548 | Generic `errno` string error logging statement. |
| 549 | |
| 550 | `+BT_LOGF_ERRNO("initial message", "format string", ...)+`:: |
| 551 | Generic `errno` string fatal logging statement. |
| 552 | |
| 553 | |
| 554 | [[lib-logging-statements]] |
| 555 | ==== Library-specific logging statement macros |
| 556 | |
| 557 | The Babeltrace library contains an internal logging API based on the |
| 558 | generic logging framework. You can use it to log known Babeltrace |
| 559 | objects without having to manually log each member. |
| 560 | |
| 561 | See <<logging-instrument-c-file-lib,Instrument a library C source file>> |
| 562 | and <<logging-instrument-h-file-lib,Instrument a library C header file>> to |
| 563 | learn how to be able to use the following macros. |
| 564 | |
| 565 | The library logging statement macros are named `+BT_LIB_LOG*()+` instead |
| 566 | of `+BT_LOG*()+`: |
| 567 | |
| 568 | `+BT_LIB_LOGT("format string", ...)+`:: |
| 569 | Library trace logging statement. |
| 570 | |
| 571 | `+BT_LIB_LOGD("format string", ...)+`:: |
| 572 | Library debug logging statement. |
| 573 | |
| 574 | `+BT_LIB_LOGI("format string", ...)+`:: |
| 575 | Library info logging statement. |
| 576 | |
| 577 | `+BT_LIB_LOGW("format string", ...)+`:: |
| 578 | Library warning logging statement. |
| 579 | |
| 580 | `+BT_LIB_LOGE("format string", ...)+`:: |
| 581 | Library error logging statement. |
| 582 | |
| 583 | `+BT_LIB_LOGF("format string", ...)+`:: |
| 584 | Library fatal logging statement. |
| 585 | |
| 586 | `+BT_LIB_LOGW_APPEND_CAUSE("format string", ...)+`:: |
| 587 | Library warning logging statement, and unconditional error cause |
| 588 | appending. |
| 589 | |
| 590 | `+BT_LIB_LOGE_APPEND_CAUSE("format string", ...)+`:: |
| 591 | Library error logging statement, and unconditional error cause |
| 592 | appending. |
| 593 | |
| 594 | `+BT_LIB_LOGF_APPEND_CAUSE("format string", ...)+`:: |
| 595 | Library fatal logging statement, and unconditional error cause |
| 596 | appending. |
| 597 | |
| 598 | The macros above accept the typical `printf()` conversion specifiers |
| 599 | with the following limitations: |
| 600 | |
| 601 | * The `+*+` width specifier is not accepted. |
| 602 | * The `+*+` precision specifier is not accepted. |
| 603 | * The `j` and `t` length modifiers are not accepted. |
| 604 | * The `n` format specifier is not accepted. |
| 605 | * The format specifiers defined in `<inttypes.h>` are not accepted, |
| 606 | except for `PRId64`, `PRIu64`, `PRIx64`, `PRIX64`, `PRIo64`, and |
| 607 | `PRIi64`. |
| 608 | |
| 609 | The Babeltrace library custom conversion specifier is accepted. Its |
| 610 | syntax is either `%!u` to format a UUID (`bt_uuid` type), or: |
| 611 | |
| 612 | . Introductory `%!` sequence. |
| 613 | |
| 614 | . **Optional**: `[` followed by a custom prefix for the printed fields |
| 615 | of this specifier, followed by `]`. The standard form is to end this |
| 616 | prefix with `-` so that, for example, with the prefix `tc-`, the |
| 617 | complete field name becomes `tc-addr`. |
| 618 | |
| 619 | . **Optional**: `pass:[+]` to print extended object members. This |
| 620 | depends on the provided format specifier. |
| 621 | |
| 622 | . Format specifier (see below). |
| 623 | |
| 624 | The available format specifiers are: |
| 625 | |
| 626 | [options="header,autowidth",cols="3"] |
| 627 | |=== |
| 628 | |Specifier |
| 629 | |Object |
| 630 | |Expected C type |
| 631 | |
| 632 | |`F` |
| 633 | |Trace IR field class |
| 634 | |`+const struct bt_field_class *+` |
| 635 | |
| 636 | |`f` |
| 637 | |Trace IR field |
| 638 | |`+const struct bt_field *+` |
| 639 | |
| 640 | |`P` |
| 641 | |Trace IR field path |
| 642 | |`+const struct bt_field_path *+` |
| 643 | |
| 644 | |`E` |
| 645 | |Trace IR event class |
| 646 | |`+const struct bt_event_class *+` |
| 647 | |
| 648 | |`e` |
| 649 | |Trace IR event |
| 650 | |`+const struct bt_event *+` |
| 651 | |
| 652 | |`S` |
| 653 | |Trace IR stream class. |
| 654 | |`+const struct bt_stream_class *+` |
| 655 | |
| 656 | |`s` |
| 657 | |Trace IR stream |
| 658 | |`+const struct bt_stream *+` |
| 659 | |
| 660 | |`a` |
| 661 | |Trace IR packet |
| 662 | |`+const struct bt_packet *+` |
| 663 | |
| 664 | |`T` |
| 665 | |Trace IR trace class |
| 666 | |`+const struct bt_trace_class *+` |
| 667 | |
| 668 | |`t` |
| 669 | |Trace IR trace |
| 670 | |`+const struct bt_trace *+` |
| 671 | |
| 672 | |`K` |
| 673 | |Trace IR clock class |
| 674 | |`+const struct bt_clock_class *+` |
| 675 | |
| 676 | |`k` |
| 677 | |Trace IR clock snapshot |
| 678 | |`+const struct bt_clock_snapshot *+` |
| 679 | |
| 680 | |`v` |
| 681 | |Value object |
| 682 | |`+const struct bt_value *+` |
| 683 | |
| 684 | |`R` |
| 685 | |Integer range set |
| 686 | |`const struct bt_integer_range_set *` |
| 687 | |
| 688 | |`n` |
| 689 | |Message |
| 690 | |`+const struct bt_message *+` |
| 691 | |
| 692 | |`i` |
| 693 | |Message iterator |
| 694 | |`struct bt_message_iterator *` |
| 695 | |
| 696 | |`C` |
| 697 | |Component class |
| 698 | |`struct bt_component_class *` |
| 699 | |
| 700 | |`c` |
| 701 | |Component |
| 702 | |`+const struct bt_component *+` |
| 703 | |
| 704 | |`p` |
| 705 | |Port |
| 706 | |`+const struct bt_port *+` |
| 707 | |
| 708 | |`x` |
| 709 | |Connection |
| 710 | |`+const struct bt_connection *+` |
| 711 | |
| 712 | |`g` |
| 713 | |Graph |
| 714 | |`+const struct bt_graph *+` |
| 715 | |
| 716 | |`z` |
| 717 | |Interrupter |
| 718 | |`+struct bt_interrupter *+` |
| 719 | |
| 720 | |`l` |
| 721 | |Plugin |
| 722 | |`+const struct bt_plugin *+` |
| 723 | |
| 724 | |`r` |
| 725 | |Error cause |
| 726 | |`+const struct bt_error_cause *+` |
| 727 | |
| 728 | |`o` |
| 729 | |Object pool |
| 730 | |`+const struct bt_object_pool *+` |
| 731 | |
| 732 | |`O` |
| 733 | |Object |
| 734 | |`+const struct bt_object *+` |
| 735 | |=== |
| 736 | |
| 737 | Conversion specifier examples: |
| 738 | |
| 739 | * `%!f` |
| 740 | * `%![my-event-]+e` |
| 741 | * `%!t` |
| 742 | * `%!+F` |
| 743 | |
| 744 | The ``, `` string (comma and space) is printed between individual |
| 745 | fields, but **not after the last one**. Therefore, you must put this |
| 746 | separator in the format string between two conversion specifiers, for |
| 747 | example: |
| 748 | |
| 749 | [source,c] |
| 750 | ---- |
| 751 | BT_LIB_LOGW("Message: count=%u, %!E, %!+K", count, event_class, clock_class); |
| 752 | ---- |
| 753 | |
| 754 | Example with a custom prefix: |
| 755 | |
| 756 | [source,c] |
| 757 | ---- |
| 758 | BT_LIB_LOGI("Some message: %![ec-a-]e, %![ec-b-]+e", ec_a, ec_b); |
| 759 | ---- |
| 760 | |
| 761 | It is safe to pass `NULL` as any Babeltrace object parameter: the macros |
| 762 | only print its null address. |
| 763 | |
| 764 | WARNING: Build-time `printf()` format checks are disabled for the |
| 765 | `+BT_LIB_LOG*()+` macros because there are custom conversion specifiers, |
| 766 | so make sure to test your logging statements. |
| 767 | |
| 768 | |
| 769 | [[comp-logging-statements]] |
| 770 | ==== Component-specific logging statement macros |
| 771 | |
| 772 | There are available logging macros for components. They prepend a prefix |
| 773 | including the component's name to the logging message. |
| 774 | |
| 775 | See <<logging-instrument-c-file-compcls,Instrument a component class C |
| 776 | source file>> and <<logging-instrument-h-file-compcls,Instrument a |
| 777 | component class C header file>> to learn how to be able to use the |
| 778 | following macros. |
| 779 | |
| 780 | The component logging statement macros are named `+BT_COMP_LOG*()+` |
| 781 | instead of `+BT_LOG*()+`: |
| 782 | |
| 783 | `+BT_COMP_LOGT("format string", ...)+`:: |
| 784 | Component trace logging statement. |
| 785 | |
| 786 | `+BT_COMP_LOGD("format string", ...)+`:: |
| 787 | Component debug logging statement. |
| 788 | |
| 789 | `+BT_COMP_LOGI("format string", ...)+`:: |
| 790 | Component info logging statement. |
| 791 | |
| 792 | `+BT_COMP_LOGW("format string", ...)+`:: |
| 793 | Component warning logging statement. |
| 794 | |
| 795 | `+BT_COMP_LOGE("format string", ...)+`:: |
| 796 | Component error logging statement. |
| 797 | |
| 798 | `+BT_COMP_LOGF("format string", ...)+`:: |
| 799 | Component fatal logging statement. |
| 800 | |
| 801 | `+BT_COMP_LOGT_STR("preformatted string")+`:: |
| 802 | Component preformatted string trace logging statement. |
| 803 | |
| 804 | `+BT_COMP_LOGD_STR("preformatted string")+`:: |
| 805 | Component preformatted string debug logging statement. |
| 806 | |
| 807 | `+BT_COMP_LOGI_STR("preformatted string")+`:: |
| 808 | Component preformatted string info logging statement. |
| 809 | |
| 810 | `+BT_COMP_LOGW_STR("preformatted string")+`:: |
| 811 | Component preformatted string warning logging statement. |
| 812 | |
| 813 | `+BT_COMP_LOGE_STR("preformatted string")+`:: |
| 814 | Component preformatted string error logging statement. |
| 815 | |
| 816 | `+BT_COMP_LOGF_STR("preformatted string")+`:: |
| 817 | Component preformatted string fatal logging statement. |
| 818 | |
| 819 | `+BT_COMP_LOGT_ERRNO("initial message", "format string", ...)+`:: |
| 820 | Component `errno` string trace logging statement. |
| 821 | |
| 822 | `+BT_COMP_LOGD_ERRNO("initial message", "format string", ...)+`:: |
| 823 | Component `errno` string debug logging statement. |
| 824 | |
| 825 | `+BT_COMP_LOGI_ERRNO("initial message", "format string", ...)+`:: |
| 826 | Component `errno` string info logging statement. |
| 827 | |
| 828 | `+BT_COMP_LOGW_ERRNO("initial message", "format string", ...)+`:: |
| 829 | Component `errno` string warning logging statement. |
| 830 | |
| 831 | `+BT_COMP_LOGE_ERRNO("initial message", "format string", ...)+`:: |
| 832 | Component `errno` string error logging statement. |
| 833 | |
| 834 | `+BT_COMP_LOGF_ERRNO("initial message", "format string", ...)+`:: |
| 835 | Component `errno` string fatal logging statement. |
| 836 | |
| 837 | `+BT_COMP_LOGT_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 838 | Component memory trace logging statement. |
| 839 | |
| 840 | `+BT_COMP_LOGD_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 841 | Component memory debug logging statement. |
| 842 | |
| 843 | `+BT_COMP_LOGI_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 844 | Component memory info logging statement. |
| 845 | |
| 846 | `+BT_COMP_LOGW_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 847 | Component memory warning logging statement. |
| 848 | |
| 849 | `+BT_COMP_LOGE_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 850 | Component memory error logging statement. |
| 851 | |
| 852 | `+BT_COMP_LOGF_MEM(data_ptr, data_size, "format string", ...)+`:: |
| 853 | Component memory fatal logging statement. |
| 854 | |
| 855 | |
| 856 | ==== Conditional logging |
| 857 | |
| 858 | `+BT_LOG_IF(cond, statement)+`:: |
| 859 | Execute `statement` only if `cond` is true. |
| 860 | + |
| 861 | Example: |
| 862 | + |
| 863 | -- |
| 864 | [source,c] |
| 865 | ---- |
| 866 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); |
| 867 | ---- |
| 868 | -- |
| 869 | |
| 870 | To check the <<build-time-log-level,build-time log level>>: |
| 871 | |
| 872 | [source,c] |
| 873 | ---- |
| 874 | #if BT_LOG_ENABLED_DEBUG |
| 875 | ... |
| 876 | #endif |
| 877 | ---- |
| 878 | |
| 879 | This tests if the _DEBUG_ level was enabled at build time. This means |
| 880 | that the current, <<run-time-log-level,run-time log level>> _could_ be |
| 881 | _DEBUG_, but it could also be higher. The rule of thumb is to use only |
| 882 | logging statements at the same level in a `BT_LOG_ENABLED_*` conditional |
| 883 | block. |
| 884 | |
| 885 | The available definitions for build-time conditions are: |
| 886 | |
| 887 | * `BT_LOG_ENABLED_TRACE` |
| 888 | * `BT_LOG_ENABLED_DEBUG` |
| 889 | * `BT_LOG_ENABLED_INFO` |
| 890 | * `BT_LOG_ENABLED_WARNING` |
| 891 | * `BT_LOG_ENABLED_ERROR` |
| 892 | * `BT_LOG_ENABLED_FATAL` |
| 893 | |
| 894 | To check the current, <<run-time-log-level,run-time log level>>: |
| 895 | |
| 896 | [source,c] |
| 897 | ---- |
| 898 | if (BT_LOG_ON_DEBUG) { |
| 899 | ... |
| 900 | } |
| 901 | ---- |
| 902 | |
| 903 | This tests if the _DEBUG_ log level is dynamically turned on |
| 904 | (implies that it's also enabled at build time). This check could have a |
| 905 | noticeable impact on performance. |
| 906 | |
| 907 | The available definitions for run-time conditions are: |
| 908 | |
| 909 | * `BT_LOG_ON_TRACE` |
| 910 | * `BT_LOG_ON_DEBUG` |
| 911 | * `BT_LOG_ON_INFO` |
| 912 | * `BT_LOG_ON_WARNING` |
| 913 | * `BT_LOG_ON_ERROR` |
| 914 | * `BT_LOG_ON_FATAL` |
| 915 | |
| 916 | Those macros check the module-specific log level symbol (defined by |
| 917 | `BT_LOG_OUTPUT_LEVEL`). |
| 918 | |
| 919 | Never, ever write code which would be executed only to compute the |
| 920 | fields of a logging statement outside a conditional logging scope, |
| 921 | for example: |
| 922 | |
| 923 | [source,c] |
| 924 | ---- |
| 925 | int number = get_number_of_event_classes_with_property_x(...); |
| 926 | BT_LOGD("Bla bla: number=%d", number); |
| 927 | ---- |
| 928 | |
| 929 | Do this instead: |
| 930 | |
| 931 | [source,c] |
| 932 | ---- |
| 933 | if (BT_LOG_ON_DEBUG) { |
| 934 | int number = get_number_of_event_classes_with_property_x(...); |
| 935 | BT_LOGD("Bla bla: number=%d", number); |
| 936 | } |
| 937 | ---- |
| 938 | |
| 939 | Or even this: |
| 940 | |
| 941 | [source,c] |
| 942 | ---- |
| 943 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); |
| 944 | ---- |
| 945 | |
| 946 | |
| 947 | === Guides |
| 948 | |
| 949 | [[logging-instrument-c-file-gen]] |
| 950 | ==== Instrument a C source file (generic) |
| 951 | |
| 952 | To instrument a C source file (`.c`): |
| 953 | |
| 954 | . At the top of the file, before the first `#include` line (if any), |
| 955 | define your file's <<choose-a-logging-tag,logging tag>> name: |
| 956 | + |
| 957 | -- |
| 958 | [source,c] |
| 959 | ---- |
| 960 | #define BT_LOG_TAG "SUBSYS/MY-MODULE/MY-FILE" |
| 961 | ---- |
| 962 | -- |
| 963 | |
| 964 | . Below the line above, define the source file's log level expression, |
| 965 | `BT_LOG_OUTPUT_LEVEL`. This expression is evaluated for each |
| 966 | <<gen-logging-statements,logging statement>> to know the current |
| 967 | <<run-time-log-level,run-time log level>>. |
| 968 | + |
| 969 | Examples: |
| 970 | + |
| 971 | [source,c] |
| 972 | ---- |
| 973 | /* Global log level variable */ |
| 974 | #define BT_LOG_OUTPUT_LEVEL module_global_log_level |
| 975 | ---- |
| 976 | + |
| 977 | [source,c] |
| 978 | ---- |
| 979 | /* Local log level variable; must exist where you use BT_LOG*() */ |
| 980 | #define BT_LOG_OUTPUT_LEVEL log_level |
| 981 | ---- |
| 982 | + |
| 983 | [source,c] |
| 984 | ---- |
| 985 | /* Object's log level; `obj` must exist where you use BT_LOG*() */ |
| 986 | #define BT_LOG_OUTPUT_LEVEL (obj->log_level) |
| 987 | ---- |
| 988 | |
| 989 | . Include `"logging/log.h"`: |
| 990 | + |
| 991 | [source,c] |
| 992 | ---- |
| 993 | #include "logging/log.h" |
| 994 | ---- |
| 995 | |
| 996 | . In the file, instrument your code with the |
| 997 | <<gen-logging-statements,generic logging statement macros>>. |
| 998 | |
| 999 | |
| 1000 | [[logging-instrument-h-file-gen]] |
| 1001 | ==== Instrument a C header file (generic) |
| 1002 | |
| 1003 | To instrument a C header file (`.h`), if you have `static inline` |
| 1004 | functions in it: |
| 1005 | |
| 1006 | . Do not include `"logging/log.h"`! |
| 1007 | |
| 1008 | . Do one of: |
| 1009 | |
| 1010 | .. In the file, instrument your code with the |
| 1011 | <<gen-logging-statements,generic logging statement macros>>, making |
| 1012 | each of them conditional to the existence of the macro you're using: |
| 1013 | + |
| 1014 | [source,c] |
| 1015 | ---- |
| 1016 | static inline |
| 1017 | int some_function(int x) |
| 1018 | { |
| 1019 | /* ... */ |
| 1020 | |
| 1021 | #ifdef BT_LOGT |
| 1022 | BT_LOGT(...); |
| 1023 | #endif |
| 1024 | |
| 1025 | /* ... */ |
| 1026 | |
| 1027 | #ifdef BT_LOGW_STR |
| 1028 | BT_LOGW_STR(...); |
| 1029 | #endif |
| 1030 | |
| 1031 | /* ... */ |
| 1032 | } |
| 1033 | ---- |
| 1034 | + |
| 1035 | The C source files which include this header file determine if logging |
| 1036 | is enabled or not for them, and if so, what is their |
| 1037 | <<choose-a-logging-tag,logging tag>> and <<run-time-log-level,run-time |
| 1038 | log level>> expression. |
| 1039 | |
| 1040 | .. Require that logging be enabled: |
| 1041 | + |
| 1042 | [source,c] |
| 1043 | ---- |
| 1044 | /* Protection: this file uses BT_LOG*() macros directly */ |
| 1045 | #ifndef BT_LOG_SUPPORTED |
| 1046 | # error Please include "logging/log.h" before including this file. |
| 1047 | #endif |
| 1048 | ---- |
| 1049 | + |
| 1050 | Then, in the file, instrument your code with the |
| 1051 | <<gen-logging-statements,generic logging statement macros>>. |
| 1052 | |
| 1053 | |
| 1054 | [[logging-instrument-c-file-lib]] |
| 1055 | ==== Instrument a library C source file |
| 1056 | |
| 1057 | To instrument a library C source file (`.c`): |
| 1058 | |
| 1059 | . At the top of the file, before the first `#include` line (if any), |
| 1060 | define your file's <<choose-a-logging-tag,logging tag>> name (this |
| 1061 | tag must start with `LIB/`): |
| 1062 | + |
| 1063 | -- |
| 1064 | [source,c] |
| 1065 | ---- |
| 1066 | #define BT_LOG_TAG "LIB/THE-FILE" |
| 1067 | ---- |
| 1068 | -- |
| 1069 | |
| 1070 | . Include `"lib/logging.h"`: |
| 1071 | + |
| 1072 | [source,c] |
| 1073 | ---- |
| 1074 | #include "lib/logging.h" |
| 1075 | ---- |
| 1076 | |
| 1077 | . In the file, instrument your code with the |
| 1078 | <<lib-logging-statements,library logging statement macros>> or with |
| 1079 | the <<gen-logging-statements,generic logging statement macros>>. |
| 1080 | |
| 1081 | |
| 1082 | [[logging-instrument-h-file-lib]] |
| 1083 | ==== Instrument a library C header file |
| 1084 | |
| 1085 | To instrument a library C header file (`.h`), if you have `static |
| 1086 | inline` functions in it: |
| 1087 | |
| 1088 | . Do not include `"lib/logging.h"`! |
| 1089 | |
| 1090 | . Require that library logging be enabled: |
| 1091 | + |
| 1092 | [source,c] |
| 1093 | ---- |
| 1094 | /* Protection: this file uses BT_LIB_LOG*() macros directly */ |
| 1095 | #ifndef BT_LIB_LOG_SUPPORTED |
| 1096 | # error Please include "lib/logging.h" before including this file. |
| 1097 | #endif |
| 1098 | ---- |
| 1099 | |
| 1100 | . In the file, instrument your code with the |
| 1101 | <<lib-logging-statements,library logging statement macros>> or with |
| 1102 | the <<gen-logging-statements,generic logging statement macros>>. |
| 1103 | |
| 1104 | |
| 1105 | [[logging-instrument-c-file-compcls]] |
| 1106 | ==== Instrument a component class C source file |
| 1107 | |
| 1108 | To instrument a component class C source file (`.c`): |
| 1109 | |
| 1110 | . At the top of the file, before the first `#include` line (if any), |
| 1111 | define your file's <<choose-a-logging-tag,logging tag>> name (this tag |
| 1112 | must start with `PLUGIN/` followed by the component class identifier): |
| 1113 | + |
| 1114 | -- |
| 1115 | [source,c] |
| 1116 | ---- |
| 1117 | #define BT_LOG_TAG "PLUGIN/SRC.MY-PLUGIN.MY-SRC" |
| 1118 | ---- |
| 1119 | -- |
| 1120 | |
| 1121 | . Below the line above, define the source file's log level expression, |
| 1122 | `BT_LOG_OUTPUT_LEVEL`. This expression is evaluated for each |
| 1123 | <<comp-logging-statements,logging statement>> to know the current |
| 1124 | <<run-time-log-level,run-time log level>>. |
| 1125 | + |
| 1126 | For a component class file, it is usually a member of a local component |
| 1127 | private structure variable: |
| 1128 | + |
| 1129 | [source,c] |
| 1130 | ---- |
| 1131 | #define BT_LOG_OUTPUT_LEVEL (my_comp->log_level) |
| 1132 | ---- |
| 1133 | |
| 1134 | . Below the line above, define `BT_COMP_LOG_SELF_COMP` to an expression |
| 1135 | which, evaluated in the context of the |
| 1136 | <<comp-logging-statements,logging statements>>, evaluates to the self |
| 1137 | component address (`+bt_self_component *+`) of the component. |
| 1138 | + |
| 1139 | This is usually a member of a local component private structure |
| 1140 | variable: |
| 1141 | + |
| 1142 | [source,c] |
| 1143 | ---- |
| 1144 | #define BT_COMP_LOG_SELF_COMP (my_comp->self_comp) |
| 1145 | ---- |
| 1146 | |
| 1147 | . Include `"logging/comp-logging.h"`: |
| 1148 | + |
| 1149 | [source,c] |
| 1150 | ---- |
| 1151 | #include "logging/comp-logging.h" |
| 1152 | ---- |
| 1153 | |
| 1154 | . In the component initialization method, make sure to set the |
| 1155 | component private structure's log level member to the initial |
| 1156 | component's log level: |
| 1157 | + |
| 1158 | [source,c] |
| 1159 | ---- |
| 1160 | struct my_comp { |
| 1161 | bt_logging_level log_level; |
| 1162 | /* ... */ |
| 1163 | }; |
| 1164 | |
| 1165 | BT_HIDDEN |
| 1166 | bt_self_component_status my_comp_init( |
| 1167 | bt_self_component_source *self_comp_src, |
| 1168 | bt_value *params, void *init_method_data) |
| 1169 | { |
| 1170 | struct my_comp *my_comp = g_new0(struct my_comp, 1); |
| 1171 | bt_self_component *self_comp = |
| 1172 | bt_self_component_source_as_self_component(self_comp_src); |
| 1173 | const bt_component *comp = bt_self_component_as_component(self_comp); |
| 1174 | |
| 1175 | BT_ASSERT(my_comp); |
| 1176 | my_comp->log_level = bt_component_get_logging_level(comp); |
| 1177 | |
| 1178 | /* ... */ |
| 1179 | } |
| 1180 | ---- |
| 1181 | |
| 1182 | . In the file, instrument your code with the |
| 1183 | <<comp-logging-statements,component logging statement macros>>. |
| 1184 | |
| 1185 | |
| 1186 | [[logging-instrument-h-file-compcls]] |
| 1187 | ==== Instrument a component class C header file |
| 1188 | |
| 1189 | To instrument a component class C header file (`.h`), if you have |
| 1190 | `static inline` functions in it: |
| 1191 | |
| 1192 | . Do not include `"logging/comp-logging.h"`! |
| 1193 | |
| 1194 | . Require that component logging be enabled: |
| 1195 | + |
| 1196 | [source,c] |
| 1197 | ---- |
| 1198 | /* Protection: this file uses BT_COMP_LOG*() macros directly */ |
| 1199 | #ifndef BT_COMP_LOG_SUPPORTED |
| 1200 | # error Please include "logging/comp-logging.h" before including this file. |
| 1201 | #endif |
| 1202 | ---- |
| 1203 | |
| 1204 | . In the file, instrument your code with the |
| 1205 | <<comp-logging-statements,component logging statement macros>>. |
| 1206 | |
| 1207 | |
| 1208 | [[choose-a-logging-tag]] |
| 1209 | ==== Choose a logging tag |
| 1210 | |
| 1211 | Each logging-enabled C source file must define `BT_LOG_TAG` to a logging |
| 1212 | tag. A logging tag is a namespace to identify the logging messages of |
| 1213 | this specific source file. |
| 1214 | |
| 1215 | In general, a logging tag name _must_ be only uppercase letters, digits, |
| 1216 | and the `-`, `.`, and `/` characters. |
| 1217 | |
| 1218 | Use `/` to show the subsystem to source file hierarchy. |
| 1219 | |
| 1220 | For the Babeltrace library, start with `LIB/`. |
| 1221 | |
| 1222 | For the CTF writer library, start with `CTF-WRITER/`. |
| 1223 | |
| 1224 | For component classes, use: |
| 1225 | |
| 1226 | [verse] |
| 1227 | `PLUGIN/__CCTYPE__.__PNAME__.__CCNAME__[/__FILE__]` |
| 1228 | |
| 1229 | With: |
| 1230 | |
| 1231 | `__CCTYPE__`:: |
| 1232 | Component class's type (`SRC`, `FLT`, or `SINK`). |
| 1233 | |
| 1234 | `__PNAME__`:: |
| 1235 | Plugin's name. |
| 1236 | |
| 1237 | `__CCNAME__`:: |
| 1238 | Component class's name. |
| 1239 | |
| 1240 | `__FILE__`:: |
| 1241 | Additional information to specify the source file name or module. |
| 1242 | |
| 1243 | For plugins (files common to many component classes), use: |
| 1244 | |
| 1245 | [verse] |
| 1246 | `PLUGIN/__PNAME__[/__FILE__]` |
| 1247 | |
| 1248 | With: |
| 1249 | |
| 1250 | `__PNAME__`:: |
| 1251 | Plugin's name. |
| 1252 | |
| 1253 | `__FILE__`:: |
| 1254 | Additional information to specify the source file name or module. |
| 1255 | |
| 1256 | |
| 1257 | [[choose-a-log-level]] |
| 1258 | ==== Choose a log level |
| 1259 | |
| 1260 | Choosing the appropriate level for your logging statement is very |
| 1261 | important. |
| 1262 | |
| 1263 | [options="header,autowidth",cols="1,2,3a,4"] |
| 1264 | |=== |
| 1265 | |Log level |Description |Use cases |Expected impact on performance |
| 1266 | |
| 1267 | |_FATAL_ |
| 1268 | | |
| 1269 | The program, library, or plugin cannot continue to work in this |
| 1270 | condition: it must be terminated immediately. |
| 1271 | |
| 1272 | A _FATAL_-level logging statement should always be followed by |
| 1273 | `abort()`. |
| 1274 | | |
| 1275 | * Unexpected return values from system calls. |
| 1276 | * Logic error in internal code, for example an unexpected value in a |
| 1277 | `switch` statement. |
| 1278 | * Failed assertion (within `BT_ASSERT()`). |
| 1279 | * Unsatisfied library precondition (within `BT_ASSERT_PRE()` or |
| 1280 | `BT_ASSERT_PRE_DEV()`). |
| 1281 | * Unsatisfied library postcondition (within `BT_ASSERT_POST()` or |
| 1282 | `BT_ASSERT_POST_DEV()`). |
| 1283 | |Almost none: always enabled. |
| 1284 | |
| 1285 | |_ERROR_ |
| 1286 | | |
| 1287 | An important error which is somewhat not fatal, that is, the program, |
| 1288 | library, or plugin can continue to work after this, but you judge that |
| 1289 | it should be reported to the user. |
| 1290 | |
| 1291 | Usually, the program cannot recover from such an error, but it can at |
| 1292 | least exit cleanly. |
| 1293 | | |
| 1294 | * Memory allocation errors. |
| 1295 | * Wrong component initialization parameters. |
| 1296 | * Corrupted, unrecoverable trace data. |
| 1297 | * Failed to perform an operation which should work considering the |
| 1298 | implementation and the satisfied preconditions. For example, the |
| 1299 | failure to create an empty object (no parameters): most probably |
| 1300 | failed internally because of an allocation error. |
| 1301 | * Almost any error in terminal elements: CLI and plugins. |
| 1302 | |Almost none: always enabled. |
| 1303 | |
| 1304 | |_WARNING_ |
| 1305 | | |
| 1306 | An error which still allows the execution to continue, but you judge |
| 1307 | that it should be reported to the user. |
| 1308 | |
| 1309 | _WARNING_-level logging statements are for any error or weird action |
| 1310 | that is directly or indirectly caused by the user, often through some |
| 1311 | bad input data. For example, not having enough memory is considered |
| 1312 | beyond the user's control, so we always log memory errors with an |
| 1313 | _ERROR_ level (not _FATAL_ because we usually don't abort in this |
| 1314 | condition). |
| 1315 | | |
| 1316 | * Missing data within something that is expected to have it, but there's |
| 1317 | an alternative. |
| 1318 | * Invalid file, but recoverable/fixable. |
| 1319 | |Almost none: always enabled. |
| 1320 | |
| 1321 | |_INFO_ |
| 1322 | | |
| 1323 | Any useful information which a non-developer user would possibly |
| 1324 | understand. |
| 1325 | |
| 1326 | Anything logged with this level must _not_ happen repetitively on the |
| 1327 | fast path, that is, nothing related to each message, for example. This |
| 1328 | level is used for sporadic and one-shot events. |
| 1329 | | |
| 1330 | * CLI or component configuration report. |
| 1331 | * Successful plugin, component, or message iterator initialization. |
| 1332 | * In the library: anything related to plugins, graphs, component |
| 1333 | classes, components, message iterators, connections, and ports which |
| 1334 | is not on the fast path. |
| 1335 | * Successful connection to or disconnection from another system. |
| 1336 | * An _optional_ subsystem cannot be loaded. |
| 1337 | * An _optional_ field/datum cannot be found. |
| 1338 | | |
| 1339 | Very little: always enabled. |
| 1340 | |
| 1341 | |_DEBUG_ |
| 1342 | | |
| 1343 | Something that only Babeltrace developers would be interested into, |
| 1344 | which can occur on the fast path, but not more often than once per |
| 1345 | message. |
| 1346 | |
| 1347 | The _DEBUG_ level is the default <<build-time-log-level,build-time log |
| 1348 | level>> as, since it's not _too_ verbose, the performance is similar to |
| 1349 | an _INFO_ build. |
| 1350 | | |
| 1351 | * Object construction and destruction. |
| 1352 | * Object recycling (except fields). |
| 1353 | * Object copying (except fields and values). |
| 1354 | * Object freezing (whatever the type, as freezing only occurs in |
| 1355 | developer mode). |
| 1356 | * Object interruption. |
| 1357 | * Calling user methods and logging the result. |
| 1358 | * Setting object properties (except fields and values). |
| 1359 | | |
| 1360 | Noticeable, but not as much as the _TRACE_ level: could be executed |
| 1361 | in production if you're going to need a thorough log for support |
| 1362 | tickets without having to rebuild the project. |
| 1363 | |
| 1364 | |_TRACE_ |
| 1365 | | |
| 1366 | Low-level debugging context information (anything that does not fit the |
| 1367 | other log levels). More appropriate for tracing in general. |
| 1368 | | |
| 1369 | * Reference count change. |
| 1370 | * Fast path, low level state machine's state change. |
| 1371 | * Get or set an object's property. |
| 1372 | * Object comparison's intermediate results. |
| 1373 | |Huge: not executed in production. |
| 1374 | |=== |
| 1375 | |
| 1376 | [IMPORTANT] |
| 1377 | -- |
| 1378 | Make sure not to use a _WARNING_ (or higher) log level when the |
| 1379 | condition leading to the logging statement can occur under normal |
| 1380 | circumstances. |
| 1381 | |
| 1382 | For example, a public function to get some object or |
| 1383 | property from an object by name or key that fails to find the value is |
| 1384 | not a warning scenario: the user could legitimately use this function to |
| 1385 | check if the name/key exists in the object. In this case, use the |
| 1386 | _TRACE_ level (or do not log at all). |
| 1387 | -- |
| 1388 | |
| 1389 | |
| 1390 | [[message]] |
| 1391 | ==== Write an appropriate message |
| 1392 | |
| 1393 | Follow those rules when you write a logging statement's message: |
| 1394 | |
| 1395 | * Use an English sentence which starts with a capital letter. |
| 1396 | |
| 1397 | * Start the sentence with the appropriate verb tense depending on the |
| 1398 | context. For example: |
| 1399 | + |
| 1400 | -- |
| 1401 | ** Beginning of operation (present continuous): _Creating ..._, |
| 1402 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ |
| 1403 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, |
| 1404 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is |
| 1405 | also _set_) |
| 1406 | -- |
| 1407 | + |
| 1408 | For warning and error messages, you can start the message with _Cannot_ |
| 1409 | or _Failed to_ followed by a verb if it's appropriate. |
| 1410 | |
| 1411 | * Do not include the log level in the message itself. For example, |
| 1412 | do not start the message with _Error while_ or _Warning:_. |
| 1413 | |
| 1414 | * Do not put newlines, tabs, or other special characters in the message, |
| 1415 | unless you want to log a string with such characters. Note that |
| 1416 | multiline logging messages can be hard to parse, analyze, and filter, |
| 1417 | however, so prefer multiple logging statements over a single statement |
| 1418 | with newlines. |
| 1419 | |
| 1420 | * **If there are fields that your logging statement must record**, |
| 1421 | follow the message with `:` followed by a space, then with the list of |
| 1422 | fields (more about this below). If there are no fields, end the |
| 1423 | sentence with a period. |
| 1424 | |
| 1425 | The statement's fields _must_ be a comma-separated list of |
| 1426 | `__name__=__value__` tokens. Keep `__name__` as simple as possible; use |
| 1427 | kebab case if possible. If `__value__` is a non-alphanumeric string, put |
| 1428 | it between double quotes (`"%s"` specifier). Always use the `PRId64` and |
| 1429 | `PRIu64` specifiers to log an `int64_t` or an `uint64_t` value. Use `%d` |
| 1430 | to log a boolean value. |
| 1431 | |
| 1432 | Example: |
| 1433 | |
| 1434 | "Cannot read stream data for indexing: path=\"%s\", name=\"%s\", " |
| 1435 | "stream-id=%" PRIu64 ", stream-fd=%d, " |
| 1436 | "index=%" PRIu64 ", status=%s, is-mapped=%d" |
| 1437 | |
| 1438 | By following a standard format for the statement fields, it is easier to |
| 1439 | use tools like https://www.elastic.co/products/logstash[Logstash] or |
| 1440 | even https://www.splunk.com/[Splunk] to split fields and analyze logs. |
| 1441 | |
| 1442 | Prefer the following suffixes in field names: |
| 1443 | |
| 1444 | [options="header,autowidth"] |
| 1445 | |=== |
| 1446 | |Field name suffix |Description |Format specifier |
| 1447 | |
| 1448 | |`-addr` |Memory address |`%p` |
| 1449 | |`-fd` |File descriptor |`%d` |
| 1450 | |`-fp` |File stream (`+FILE *+`) |`%p` |
| 1451 | |`-id` |Object's ID |`%" PRIu64 "` |
| 1452 | |`-index` |Index |`%" PRIu64 "` |
| 1453 | |`-name` |Object's name |`\"%s\"` |
| 1454 | |=== |
| 1455 | |
| 1456 | |
| 1457 | === Output |
| 1458 | |
| 1459 | The log is printed to the standard error stream. A log line contains the |
| 1460 | time, the process and thread IDs, the <<log-levels,log level>>, the |
| 1461 | <<choose-a-logging-tag,logging tag>>, the source's function name, file |
| 1462 | name and line number, and the <<message,message>>. |
| 1463 | |
| 1464 | When Babeltrace supports terminal color codes (depends on the |
| 1465 | `BABELTRACE_TERM_COLOR` environment variable's value and what the |
| 1466 | standard output and error streams are plugged into), _INFO_-level lines |
| 1467 | are blue, _WARNING_-level lines are yellow, and _ERROR_-level and |
| 1468 | _FATAL_-level lines are red. |
| 1469 | |
| 1470 | Log line example: |
| 1471 | |
| 1472 | ---- |
| 1473 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 |
| 1474 | ---- |
| 1475 | |
| 1476 | You can easily filter the log with `grep` or `ag`. For example, to keep |
| 1477 | only the _DEBUG_-level logging messages that the `FIELD-CLASS` module |
| 1478 | generates: |
| 1479 | |
| 1480 | ---- |
| 1481 | $ babeltrace2 --log-level=D /path/to/trace |& ag 'D FIELD-CLASS' |
| 1482 | ---- |
| 1483 | |
| 1484 | |
| 1485 | == Valgrind |
| 1486 | |
| 1487 | To use Valgrind on an application (for example, the CLI or a test) which |
| 1488 | loads libbabeltrace2, use: |
| 1489 | |
| 1490 | ---- |
| 1491 | $ G_SLICE=always-malloc G_DEBUG=gc-friendly PYTHONMALLOC=malloc \ |
| 1492 | LIBBABELTRACE2_NO_DLCLOSE=1 valgrind --leak-check=full app |
| 1493 | ---- |
| 1494 | |
| 1495 | `G_SLICE=always-malloc` and `G_DEBUG=gc-friendly` is for GLib and |
| 1496 | `PYTHONMALLOC=malloc` is for the Python interpreter, if it is used by |
| 1497 | the Python plugin provider (Valgrind will probably show a lot of errors |
| 1498 | which originate from the Python interpreter anyway). |
| 1499 | |
| 1500 | `LIBBABELTRACE2_NO_DLCLOSE=1` makes libbabeltrace2 not close the shared |
| 1501 | libraries (plugins) which it loads. You need this to see the appropriate |
| 1502 | backtrace when Valgrind shows errors. |
| 1503 | |
| 1504 | == Testing |
| 1505 | |
| 1506 | [[test-env]] |
| 1507 | === Environment |
| 1508 | |
| 1509 | `tests/utils/utils.sh` sets the environment variables for any Babeltrace |
| 1510 | test script. |
| 1511 | |
| 1512 | `utils.sh` only needs to know the path to the `tests` directory within |
| 1513 | the source and the build directories. By default, `utils.sh` assumes the |
| 1514 | build is in tree, that is, you ran `./configure` from the source's root |
| 1515 | directory, and sets the `BT_TESTS_SRCDIR` and `BT_TESTS_BUILDDIR` |
| 1516 | environment variables accordingly. You can override those variables, for |
| 1517 | example if you build out of tree. |
| 1518 | |
| 1519 | All test scripts eventually do something like this to source `utils.sh`, |
| 1520 | according to where they are located relative to the `tests` directory: |
| 1521 | |
| 1522 | [source,bash] |
| 1523 | ---- |
| 1524 | if [ "x${BT_TESTS_SRCDIR:-}" != "x" ]; then |
| 1525 | UTILSSH="$BT_TESTS_SRCDIR/utils/utils.sh" |
| 1526 | else |
| 1527 | UTILSSH="$(dirname "$0")/../utils/utils.sh" |
| 1528 | fi |
| 1529 | ---- |
| 1530 | |
| 1531 | ==== Python |
| 1532 | |
| 1533 | You can use the `tests/utils/run_python_bt2` script to run any command |
| 1534 | within an environment making the build's `bt2` Python package available. |
| 1535 | |
| 1536 | `run_python_bt2` uses <<test-env,`utils.sh`>> which needs to know the |
| 1537 | build directory, so make sure you set the `BT_TESTS_BUILDDIR` |
| 1538 | environment variable correctly _if you build out of tree_, for example: |
| 1539 | |
| 1540 | ---- |
| 1541 | $ export BT_TESTS_BUILDDIR=/path/to/build/babeltrace/tests |
| 1542 | ---- |
| 1543 | |
| 1544 | You can run any command which needs the `bt2` Python package through |
| 1545 | `run_python_bt2`, for example: |
| 1546 | |
| 1547 | ---- |
| 1548 | $ ./tests/utils/run_python_bt2 ipython3 |
| 1549 | ---- |
| 1550 | |
| 1551 | === Report format |
| 1552 | |
| 1553 | All test scripts output the test results following the |
| 1554 | https://testanything.org/[Test Anything Protocol] (TAP) format. |
| 1555 | |
| 1556 | The TAP format has two mechanisms to print additional information about |
| 1557 | a test: |
| 1558 | |
| 1559 | * Print a line starting with `#` to the standard output. |
| 1560 | + |
| 1561 | This is usually done with the `diag()` C function or the `diag` shell |
| 1562 | function. |
| 1563 | |
| 1564 | * Print to the standard error. |
| 1565 | |
| 1566 | |
| 1567 | === Python bindings |
| 1568 | |
| 1569 | The `bt2` Python package tests are located in |
| 1570 | `tests/bindings/python/bt2`. |
| 1571 | |
| 1572 | |
| 1573 | ==== Python test runner |
| 1574 | |
| 1575 | `tests/utils/python/testrunner.py` is Babeltrace's Python test runner |
| 1576 | which loads Python files containing unit tests, finds all the test |
| 1577 | cases, and runs the tests, producing a TAP report. |
| 1578 | |
| 1579 | You can see the test runner command's help with: |
| 1580 | |
| 1581 | ---- |
| 1582 | $ python3 ./tests/utils/python/testrunner.py --help |
| 1583 | ---- |
| 1584 | |
| 1585 | By default, the test runner reports failing tests (TAP's `not{nbsp}ok` |
| 1586 | line), but continues to run other tests. You can use the `--failfast` |
| 1587 | option to make the test runner fail as soon as a test fails. |
| 1588 | |
| 1589 | |
| 1590 | ==== Guides |
| 1591 | |
| 1592 | To run all the `bt2` Python package tests: |
| 1593 | |
| 1594 | * Run: |
| 1595 | + |
| 1596 | ---- |
| 1597 | $ ./tests/utils/run_python_bt2 ./tests/bindings/python/bt2/test_python_bt2 |
| 1598 | ---- |
| 1599 | + |
| 1600 | or: |
| 1601 | + |
| 1602 | ---- |
| 1603 | $ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \ |
| 1604 | ./tests/bindings/python/bt2/ -p '*.py' |
| 1605 | ---- |
| 1606 | |
| 1607 | To run **all the tests** in a test module (for example, |
| 1608 | `test_value.py`): |
| 1609 | |
| 1610 | * Run: |
| 1611 | + |
| 1612 | ---- |
| 1613 | $ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \ |
| 1614 | ./tests/bindings/python/bt2 -t test_value |
| 1615 | ---- |
| 1616 | |
| 1617 | To run a **specific test case** (for example, `RealValueTestCase` within |
| 1618 | `test_value.py`): |
| 1619 | |
| 1620 | * Run: |
| 1621 | + |
| 1622 | ---- |
| 1623 | $ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \ |
| 1624 | ./tests/bindings/python/bt2/ -t test_value.RealValueTestCase |
| 1625 | ---- |
| 1626 | |
| 1627 | To run a **specific test** (for example, |
| 1628 | `RealValueTestCase.test_assign_pos_int` within `test_value.py`): |
| 1629 | |
| 1630 | * Run: |
| 1631 | + |
| 1632 | ---- |
| 1633 | $ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \ |
| 1634 | ./tests/bindings/python/bt2/ -t test_value.RealValueTestCase.test_assign_pos_int |
| 1635 | ---- |