CONTRIBUTING.adoc

   1 = Babeltrace's contributor's guide
   2 Jérémie Galarneau, Philippe Proulx
   3 v0.1, 6 September 2017
   4 :toc:
   5 :toclevels: 5
   6
   7
   8 This is a partial contributor's guide for the
   9 http://diamon.org/babeltrace[Babeltrace] project. If you have any
  10 questions that are not answered in this guide, please post them
  11 on https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev[Babeltrace's mailing list].
  12
  13
  14 == Object reference counting and lifetime
  15
  16 This section covers the rationale behind the design of Babeltrace's
  17 object lifetime management.
  18
  19 Starting from Babeltrace 2.x, all publicly exposed objects inherit a
  20 common base: `bt_object`. This base provides a number of facilities to
  21 all objects, chief amongst which are lifetime management functions.
  22
  23 The reference count of all public objects is controlled by invoking the
  24 `bt_get()` and `bt_put()` functions which respectively increment and
  25 decrement an object's reference count.
  26
  27 As far as lifetime management in concerned, Babeltrace makes a clear
  28 distinction between regular objects, which have a single parent, and
  29 root objects, which don't.
  30
  31
  32 === The problem
  33
  34 Let us consider a problematic case to illustrate the need for this
  35 distinction.
  36
  37 A user of the CTF Writer library declares a trace, which *has* a
  38 stream class (the declaration of a stream) and that stream class, in
  39 turn, *has* an event class (the declaration of an event).
  40
  41 Nothing prevents this user from releasing his reference on any one of
  42 these objects in any order. However, all objects in the
  43 __trace--stream class--event class__ hierarchy can be retrieved
  44 from any other.
  45
  46 For instance, the user could discard his reference on both the event
  47 class and the stream class, only keeping a reference on the trace. From
  48 this trace reference, stream classes can be enumerated, providing the
  49 user with a new reference to the stream class he discarded earlier.
  50 event classes can also be enumerated from stream classes, providing the
  51 user with references to the individual event classes.
  52
  53 Conversely, the user could also hold a reference to an event class and
  54 retrieve its parent stream class. The trace, in turn, can then be
  55 retrieved from the stream class.
  56
  57 This example illustrates what could be interpreted as a circular
  58 reference dependency existing between these objects. Of course, if the
  59 objects in such a scenario were to hold references to each other (in
  60 both directions), we would be in presence of a circular ownership
  61 resulting in a leak of both objects as their reference counts would
  62 never reach zero.
  63
  64 Nonetheless, the API must offer the guarantee that holding a node to any
  65 node of the graph keeps all other reachable nodes alive.
  66
  67
  68 === The solution
  69
  70 The scheme employed in Babeltrace to break this cycle consists in the
  71 "children" holding *reverse component references* to their parents. That
  72 is, in the context of CTF IR, that event classes hold a reference to
  73 their parent stream class and stream classes hold a reference to their
  74 parent trace.
  75
  76 On the other hand, parents hold *claiming aggregation references* to
  77 their children. A claiming aggregation reference means that the object
  78 being referenced should not be deleted as long as the reference still
  79 exists. In this respect, it can be said that parents truly hold the
  80 ownership of their children, since they control their lifetime.
  81 Conversely, the reference counting mechanism is leveraged by children to
  82 notify parents that no other child indirectly exposes the parent.
  83
  84 When a parented object's reference count reaches zero, it invokes
  85 `bt_put()` on its parent and does **not** free itself. However, from
  86 that point, the object depends on its parent to signal the moment when
  87 it can be safely reclaimed.
  88
  89 The invocation of `bt_put()` by the last children holding a reference to
  90 its parent might trigger a cascade of `bt_put()` from child to parent.
  91 Eventually, a **root** object is reached. At that point, if this
  92 orphaned object's reference count reaches zero, the object invokes the
  93 destructor method defined by everyone of its children as part of their
  94 base `struct bt_object`. The key point here is that the cascade of
  95 destructor will necessarily originate from the root and propagate in
  96 preorder to the children. These children will propagate the destruction
  97 to their own children before reclaiming their own memory. This ensures
  98 that a node's pointer to its parent is *always* valid since the parent
  99 has the responsibility of tearing-down their children before cleaning
 100 themselves up.
 101
 102 Assuming a reference to an object is *acquired* by calling `bt_get()`
 103 while its reference count is zero, the object acquires, in turn, a
 104 reference on its parent using `bt_get()`. At that point, the child can
 105 be thought of as having converted its weak reference to its parent into
 106 a regular reference. That is why this reference is referred to as a
 107 *claiming* aggregation reference.
 108
 109
 110 === Caveats
 111
 112 This scheme imposes a number of strict rules defining the relation
 113 between objects:
 114
 115 * Objects may only have one parent.
 116 * Objects, beside the root, are only retrievable from their direct
 117   parent or children.
 118
 119
 120 === Example
 121
 122 The initial situation is rather simple: **User A** is holding a
 123 reference to a trace, **TC1**. As per the rules previously enounced,
 124 stream classes **SC1** and **SC2** don't hold a reference to **TC1**
 125 since their own reference counts are zero. The same holds true for
 126 **EC1**, **EC2** and **EC3** with respect to **SC1** and **SC2**.
 127
 128 image::doc/contributing-images/bt-ref01.png[]
 129
 130 In this second step, we can see that **User A** has acquired a reference
 131 on **SC2** through the trace, **TC1**.
 132
 133 The stream class's reference count transitions from zero to one,
 134 triggering the acquisition of a strong reference on **TC1** from
 135 **SC2**.
 136
 137 Hence, at this point, the trace's ownership is shared by **User A** and
 138 **SC2**.
 139
 140 image::doc/contributing-images/bt-ref02.png[]
 141
 142 Next, **User A** acquires a reference on the **EC3** event class through
 143 its parent stream class, **SC2**. Again, the transition of an object's
 144 reference count from 0 to 1 triggers the acquisition of a reference on
 145 its parent.
 146
 147 Note that SC2's reference count was incremented to 2. The trace's
 148 reference count remains unchanged.
 149
 150 image::doc/contributing-images/bt-ref03.png[]
 151
 152 **User A** decides to drop its reference on **SC2**. **SC2**'s reference
 153 count returns back to 1, everything else remaining unchanged.
 154
 155 image::doc/contributing-images/bt-ref04.png[]
 156
 157 **User A** can then decide to drop its reference on the trace. This
 158 results in a reversal of the initial situation: **User A** now owns an
 159 event, **EC3**, which is keeping everything else alive and reachable.
 160
 161 image::doc/contributing-images/bt-ref05.png[]
 162
 163 If another object, **User B**, enters the picture and acquires a
 164 reference on the **SC1** stream class, we see that **SC1**'s reference
 165 count transitioned from 0 to 1, triggering the acquisition of a
 166 reference on **TC1**.
 167
 168 image::doc/contributing-images/bt-ref06.png[]
 169
 170 **User B** hands off a reference to **EC1**, acquired through **SC1**,
 171 to another object, **User C**. The acquisition of a reference on
 172 **EC1**, which transitions from 0 to 1, triggers the acquisition of a
 173 reference on its parent, **SC1**.
 174
 175 image::doc/contributing-images/bt-ref07.png[]
 176
 177 At some point, **User A** releases its reference on **EC3**. Since
 178 **EC3**'s reference count transitions to zero, it releases its reference
 179 on **SC2**. **SC2**'s reference count, in turn, reaches zero and it
 180 releases its reference to **TC1**.
 181
 182 **TC1**'s reference count is now 1 and no further action is taken.
 183
 184 image::doc/contributing-images/bt-ref08.png[]
 185
 186 **User B** releases its reference on **SC1**. **User C** becomes the
 187 sole owner of the whole hierarchy through his ownership of **EC1**.
 188
 189 image::doc/contributing-images/bt-ref09.png[]
 190
 191 Finally, **User C** releases his ownership of **EC1**, triggering the
 192 release of the whole hierarchy. Let's walk through the reclamation of
 193 the whole graph.
 194
 195 Mirroring what happened when **User A** released its last reference on
 196 **EC3**, the release of **EC1** by **User C** causes its reference count
 197 to fall to zero.
 198
 199 This transition to zero causes **EC1** to release its reference on
 200 **SC1**. **SC1**'s reference count reaching zero causes it to release
 201 its reference on **TC1**.
 202
 203 image::doc/contributing-images/bt-ref10.png[]
 204
 205 Since the reference count of **TC1**, a root object, has reached zero,
 206 it invokes the destructor method on its children. This method is
 207 recursive and causes the stream classes to call the destructor method on
 208 their event classes.
 209
 210 The event classes are reached and, having no children of their own, are
 211 reclaimed.
 212
 213 image::doc/contributing-images/bt-ref11.png[]
 214
 215 The stream classes having destroyed their children, are then reclaimed
 216 by the trace.
 217
 218 image::doc/contributing-images/bt-ref12.png[]
 219
 220 Finally, the stream classes having been reclaimed, **TC1** is reclaimed.
 221
 222 image::doc/contributing-images/bt-ref13.png[]
 223
 224
 225 == Valgrind
 226
 227 To use Valgrind on an application (for example, the CLI or a test) which
 228 loads libbabeltrace, use:
 229
 230     $ G_SLICE=always-malloc G_DEBUG=gc-friendly PYTHONMALLOC=malloc \
 231       BABELTRACE_NO_DLCLOSE=1 valgrind --leak-check=full \
 232       --suppressions=/path/to/babeltrace/extras/valgrind/popt.supp app
 233
 234 `G_SLICE=always-malloc` and `G_DEBUG=gc-friendly` is for GLib and
 235 `PYTHONMALLOC=malloc` is for the Python interpreter, if it is used by
 236 the Python plugin provider (Valgrind will probably show a lot of errors
 237 which originate from Python interpreter anyway).
 238
 239 `BABELTRACE_NO_DLCLOSE=1` makes libbabeltrace not close the shared
 240 libraries (plugins) which it loads. This is needed to see the
 241 appropriate backtrace when Valgrind shows errors.
 242
 243
 244 == Logging
 245
 246 Logging is a great instrument for a developer to be able to collect
 247 information about a running software.
 248
 249 Babeltrace is a complex software with many layers. When a Babeltrace
 250 graph fails to run, what caused the failure? It could be caused by any
 251 component, any notification iterator, and any deeply nested validation
 252 of a CTR IR object, for example. With the appropriate logging statements
 253 manually placed in the source code, we can find the cause of a bug
 254 faster.
 255
 256 While <<log-level,care must be taken>> when placing _INFO_ to _FATAL_
 257 logging statements, you should liberally instrument your Babeltrace
 258 module with _DEBUG_ and _VERBOSE_ logging statements to help future you
 259 and other developers understand what's happening at run-time.
 260
 261
 262 === Logging API
 263
 264 The Babeltrace logging API is internal: it is not exposed to the users
 265 of the library, only to their developers. The only thing that a library
 266 user can control is the current log level of the library itself with
 267 `bt_logging_set_global_level()` and the initial library's log level with
 268 the `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable.
 269
 270 This API is based on https://github.com/wonder-mice/zf_log[zf_log], a
 271 lightweight, yet featureful, MIT-licensed core logging library for C and
 272 $$C++$$. The zf_log source files were modified to have the `BT_` and
 273 `bt_` prefixes, and other small changes, like color support.
 274
 275 The logging functions are implemented in the logging convenience
 276 library (`logging` directory).
 277
 278
 279 ==== Headers
 280
 281 The logging API headers are:
 282
 283 `<babeltrace/logging.h>`::
 284     Public header which a library user can use to control and read
 285     libbabeltrace's current log level.
 286
 287 `<babeltrace/logging-internal.h>`::
 288     Internal, generic logging API which you can use in any Babeltrace
 289     subproject. This is the translation of `zf_log.h`.
 290
 291 `<babeltrace/lib-logging-internal.h>`::
 292     Specific internal header to use within the library. This header
 293     defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide hidden
 294     symbol which is the library's current log level before including
 295     `<babeltrace/logging-internal.h>`.
 296
 297 Do not include `<babeltrace/logging-internal.h>` or
 298 `<babeltrace/lib-logging-internal.h>` in a header which contains logging
 299 statements: this header could be included in source files which define a
 300 different <<choose-a-tag,tag>>, for example. See
 301 <<logging-instrument-header, Instrument a C header file>>.
 302
 303
 304 ==== Log levels
 305
 306 The API offers the following log levels:
 307
 308 * _VERBOSE_
 309 * _DEBUG_
 310 * _INFO_
 311 * _WARN_
 312 * _ERROR_
 313 * _FATAL_
 314
 315 See <<log-level,how to decide which one to use>> below.
 316
 317 There are two important log level variables:
 318
 319 [[build-time-log-level]]Build-time, minimal log level::
 320     The minimal log level, or build-time log level, is set at build
 321     time and determines the minimal log level which can be executed.
 322     This applies to all the subprojects and modules (CLI, library,
 323     plugins, etc.).
 324 +
 325 All the logging statements with a level below this level are **not built
 326 at all**. All the logging statements with a level equal to or greater
 327 than this level _can_ be executed, depending on the
 328 <<run-time-log-level,run-time log level>>.
 329 +
 330 You can set this level at configuration time with the
 331 `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example:
 332 +
 333 --
 334 ----
 335 $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure
 336 ----
 337 --
 338 +
 339 The default build-time log level is `VERBOSE`. For optimal performance,
 340 set it to `NONE`, which effectively disables all logging in all the
 341 Babeltrace subprojects.
 342 +
 343 The library's public API provides `bt_logging_get_minimal_level()` to
 344 get the configured minimal log level.
 345
 346 [[run-time-log-level]]Run-time, dynamic log level::
 347     The dynamic log level is set at run-time and determines the current,
 348     active log level. All the logging statements with a level below this
 349     level are not executed, but they evaluate the condition. All the
 350     logging statements with a level equal to or greater than this level
 351     are executed, provided that their level is also
 352     <<build-time-log-level,enabled at build time>>.
 353 +
 354 `zf_log` has a concept of a global run-time log level which uses the
 355 `_bt_log_global_output_lvl` symbol. In practice, we never use this
 356 symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined to a
 357 module-wise or subproject-wise hidden symbol before including
 358 `<babeltrace/logging-internal.h>`. In the library,
 359 `<babeltrace/lib-logging-internal.h>` does this job: just include this
 360 header which defines `BT_LOG_OUTPUT_LEVEL` to the appropriate symbol
 361 before it includes `<babeltrace/logging-internal.h>`. In plugins, for
 362 example, there is one log level per component class, which makes log
 363 filtering easier during execution.
 364 +
 365 In libbabeltrace, the user can set the current run-time log level with
 366 the `bt_logging_set_global_level()` function, for example:
 367 +
 368 --
 369 [source,c]
 370 ----
 371 bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO);
 372 ----
 373 --
 374 +
 375 The library's initial run-time log level is defined by the
 376 `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable (`VERBOSE`, `DEBUG`,
 377 `INFO`, `WARN`, `ERROR`, `FATAL`, or `NONE`), or set to _NONE_ if this
 378 environment variable is undefined.
 379 +
 380 Other subprojects have their own way of setting their run-time log
 381 level. For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL`
 382 environment variable, and the `filter.utils.muxer` component class
 383 initializes its log level thanks to the
 384 `BABELTRACE_PLUGIN_UTILS_MUXER_FLT_LOG_LEVEL` environment variable
 385 (also _NONE_ by default).
 386 +
 387 Make sure that there is a documented way to initialize or modify the
 388 log level of your subproject or module, and that it's set to _NONE_
 389 by default.
 390
 391
 392 [[logging-statements]]
 393 ==== Logging statement macros
 394
 395 The Babeltrace logging statement macros work just like `printf()` and
 396 contain their log level in their name:
 397
 398 `BT_LOGV("format string", ...)`::
 399     Standard verbose logging statement.
 400
 401 `BT_LOGD("format string", ...)`::
 402     Standard debug logging statement.
 403
 404 `BT_LOGI("format string", ...)`::
 405     Standard info logging statement.
 406
 407 `BT_LOGW("format string", ...)`::
 408     Standard warning logging statement.
 409
 410 `BT_LOGE("format string", ...)`::
 411     Standard error logging statement.
 412
 413 `BT_LOGF("format string", ...)`::
 414     Standard fatal logging statement.
 415
 416 `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`::
 417     Memory verbose logging statement.
 418
 419 `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`::
 420     Memory debug logging statement.
 421
 422 `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`::
 423     Memory info logging statement.
 424
 425 `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`::
 426     Memory warning logging statement.
 427
 428 `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`::
 429     Memory error logging statement.
 430
 431 `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`::
 432     Memory fatal logging statement.
 433
 434 `BT_LOGV_ERRNO("initial message", "format string", ...)`::
 435         `errno` string verbose logging statement.
 436
 437 `BT_LOGD_ERRNO("initial message", "format string", ...)`::
 438         `errno` string debug logging statement.
 439
 440 `BT_LOGI_ERRNO("initial message", "format string", ...)`::
 441         `errno` string info logging statement.
 442
 443 `BT_LOGW_ERRNO("initial message", "format string", ...)`::
 444         `errno` string warning logging statement.
 445
 446 `BT_LOGE_ERRNO("initial message", "format string", ...)`::
 447         `errno` string error logging statement.
 448
 449 `BT_LOGF_ERRNO("initial message", "format string", ...)`::
 450         `errno` string fatal logging statement.
 451
 452 `BT_LOGV_STR("preformatted string")`::
 453     Preformatted string verbose logging statement.
 454
 455 `BT_LOGD_STR("preformatted string")`::
 456     Preformatted string debug logging statement.
 457
 458 `BT_LOGI_STR("preformatted string")`::
 459     Preformatted string info logging statement.
 460
 461 `BT_LOGW_STR("preformatted string")`::
 462     Preformatted string warning logging statement.
 463
 464 `BT_LOGE_STR("preformatted string")`::
 465     Preformatted string error logging statement.
 466
 467 `BT_LOGF_STR("preformatted string")`::
 468     Preformatted string fatal logging statement.
 469
 470
 471 ==== Conditional logging
 472
 473 `BT_LOG_IF(cond, statement)`::
 474     Execute `statement` only if `cond` is true.
 475 +
 476 Example:
 477 +
 478 --
 479 [source,c]
 480 ----
 481 BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i));
 482 ----
 483 --
 484
 485 To check the <<build-time-log-level,build-time log level>>:
 486
 487 [source,c]
 488 ----
 489 #if BT_LOG_ENABLED_DEBUG
 490 ...
 491 #endif
 492 ----
 493
 494 This tests if the _DEBUG_ level was enabled at build-time. This means
 495 that the current, <<run-time-log-level,dynamic log level>> _could_ be
 496 _DEBUG_, but it could also be higher. The rule of thumb is to use only
 497 logging statements at the same level in a `BT_LOG_ENABLED_*` conditional
 498 block.
 499
 500 The available definitions for build-time conditions are:
 501
 502 * `BT_LOG_ENABLED_VERBOSE`
 503 * `BT_LOG_ENABLED_DEBUG`
 504 * `BT_LOG_ENABLED_INFO`
 505 * `BT_LOG_ENABLED_WARN`
 506 * `BT_LOG_ENABLED_ERROR`
 507 * `BT_LOG_ENABLED_FATAL`
 508
 509 To check the current, <<run-time-log-level,run-time log level>>:
 510
 511 [source,c]
 512 ----
 513 if (BT_LOG_ON_DEBUG) {
 514     ...
 515 }
 516 ----
 517
 518 This tests if the _DEBUG_ log level is dynamically turned on
 519 (implies that it's also enabled at build-time). This check could have a
 520 noticeable impact on performance.
 521
 522 The available definitions for run-time conditions are:
 523
 524 * `BT_LOG_ON_VERBOSE`
 525 * `BT_LOG_ON_DEBUG`
 526 * `BT_LOG_ON_INFO`
 527 * `BT_LOG_ON_WARN`
 528 * `BT_LOG_ON_ERROR`
 529 * `BT_LOG_ON_FATAL`
 530
 531 Those macros check the subproject-specific or module-specific log level
 532 symbol (defined by `BT_LOG_OUTPUT_LEVEL`).
 533
 534 Never, ever write code which would be executed only to compute the
 535 fields of a logging statement outside a conditional logging scope,
 536 for example:
 537
 538 [source,c]
 539 ----
 540 int number = get_number_of_event_classes_with_property_x(...);
 541 BT_LOGD("Bla bla: number=%d", number);
 542 ----
 543
 544 Do this instead:
 545
 546 [source,c]
 547 ----
 548 if (BT_LOG_ON_DEBUG) {
 549     int number = get_number_of_event_classes_with_property_x(...);
 550     BT_LOGD("Bla bla: number=%d", number);
 551 }
 552 ----
 553
 554 Or even this:
 555
 556 [source,c]
 557 ----
 558 BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...));
 559 ----
 560
 561
 562 [[how-to]]
 563 === Instrument a module
 564
 565 Follow those steps to make your module loggable:
 566
 567 . In your module's root directory, create a `logging.c` file with
 568   this content:
 569 +
 570 --
 571 [source,c]
 572 ----
 573 /*
 574  * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
 575  *
 576  * Permission is hereby granted, free of charge, to any person obtaining a copy
 577  * of this software and associated documentation files (the "Software"), to deal
 578  * in the Software without restriction, including without limitation the rights
 579  * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 580  * copies of the Software, and to permit persons to whom the Software is
 581  * furnished to do so, subject to the following conditions:
 582  *
 583  * The above copyright notice and this permission notice shall be included in
 584  * all copies or substantial portions of the Software.
 585  *
 586  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 587  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 588  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 589  * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 590  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 591  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 592  * SOFTWARE.
 593  */
 594
 595 #define BT_LOG_OUTPUT_LEVEL my_module_log_level
 596 #include <babeltrace/logging-internal.h>
 597
 598 BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL");
 599 ----
 600 --
 601 +
 602 Replace `my_module_log_level` with the name of the symbol which holds
 603 the log level for your module (should be unique amongst all the log level
 604 symbols of the project). Replace `BABELTRACE_MY_MODULE_LOG_LEVEL` with
 605 the name of the environment variable from which to initialize your
 606 module's log level at construction time. `BT_LOG_INIT_LOG_LEVEL()`
 607 defines both the hidden log level symbol and a constructor which reads
 608 the environment variable and sets the log level symbol accordingly.
 609
 610 . In your module's root directory, create a `logging.h` file with
 611   this content:
 612 +
 613 --
 614 [source,c]
 615 ----
 616 #ifndef BABELTRACE_MY_MODULE_LOGGING_H
 617 #define BABELTRACE_MY_MODULE_LOGGING_H
 618
 619 /*
 620  * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
 621  *
 622  * Permission is hereby granted, free of charge, to any person obtaining a copy
 623  * of this software and associated documentation files (the "Software"), to deal
 624  * in the Software without restriction, including without limitation the rights
 625  * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 626  * copies of the Software, and to permit persons to whom the Software is
 627  * furnished to do so, subject to the following conditions:
 628  *
 629  * The above copyright notice and this permission notice shall be included in
 630  * all copies or substantial portions of the Software.
 631  *
 632  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 633  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 634  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 635  * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 636  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 637  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 638  * SOFTWARE.
 639  */
 640
 641 #define BT_LOG_OUTPUT_LEVEL my_module_log_level
 642 #include <babeltrace/logging-internal.h>
 643
 644 BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level);
 645
 646 #endif /* BABELTRACE_MY_MODULE_LOGGING_H */
 647 ----
 648 --
 649 +
 650 Replace `my_module_log_level` with the name of your module's
 651 log level symbol.
 652
 653 . Include the `logging.c` and `logging.h` in the `_SOURCES` variable
 654   of your module's object in your module's root `Makefile.am`.
 655
 656 . Add the log level initializing environment variable name to the
 657   `log_level_env_var_names` array in `cli/babeltrace.c`.
 658
 659
 660 [[logging-instrument-source]]
 661 ==== Instrument a C source file
 662
 663 To instrument a C source file (`.c`):
 664
 665 . At the top of the file, before the first `#include` line (if any),
 666   define your file's tag name and include the local `logging.h`:
 667 +
 668 --
 669 [source,c]
 670 ----
 671 #define BT_LOG_TAG "MY-MODULE-MY-FILE"
 672 #include "logging.h"
 673 ----
 674 --
 675 +
 676 A logging tag name is a namespace for a specific source file. Its name
 677 is part of every log message generated by the statements of the file. A
 678 logging tag name _must_ be only uppercase letters, digits, and the
 679 hyphen (`-`) character. See <<choose-a-tag,Choose a tag>> for
 680 a list of standard tags.
 681
 682 . Use the <<logging-statements,logging statement macros>> in the file's
 683   functions to instrument it.
 684
 685
 686 [[logging-instrument-header]]
 687 ==== Instrument a C header file
 688
 689 To instrument a C header file (`.h`), if you have `static inline`
 690 functions in it:
 691
 692 . Do not include any logging header.
 693 . Use the <<logging-statements,logging statement macros>> in the file's
 694   functions to instrument it, making each of them conditional to the
 695   existence of the macro you're using:
 696 +
 697 --
 698 [source,c]
 699 ----
 700 static inline
 701 void some_function(void)
 702 {
 703     /* ... */
 704
 705 #ifdef BT_LOGV
 706     BT_LOGV(...);
 707 #endif
 708
 709     /* ... */
 710
 711 #ifdef BT_LOGW_STR
 712     BT_LOGW_STR(...);
 713 #endif
 714
 715     /* ... */
 716 }
 717 ----
 718 --
 719 +
 720 The C source files which include this header file determine if logging
 721 is enabled or not for them (if the source file is instrumented itself),
 722 and the tag of the included header's logging statement is the same as
 723 the including C source file.
 724
 725
 726 [[choose-a-tag]]
 727 === Choose a tag
 728
 729 For plugins, the format of the tag name for a given source file _must_
 730 be:
 731
 732 [verse]
 733 PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__]
 734
 735 __PNAME__::
 736     Plugin's name.
 737
 738 __CCNAME__::
 739     Component class's name.
 740
 741 __CCTYPE__::
 742     Component class's type (`SRC`, `FLT`, or `SINK`).
 743
 744 __FILE__::
 745     Additional information to specify the source file name or module.
 746
 747 Examples:
 748
 749 * `PLUGIN-CTF-LTTNG-LIVE-SRC`
 750 * `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER`
 751 * `PLUGIN-UTILS-MUXER-FLT`
 752
 753
 754 [[log-level]]
 755 === Choose a log level
 756
 757 Choosing the appropriate level for your logging statement is very
 758 important.
 759
 760 [options="header,autowidth",cols="default,default,asciidoc,default"]
 761 |===
 762 |Log level |Description |Use cases |Impact on performance
 763
 764 |_FATAL_
 765 |The program, library, or plugin cannot continue to work in this
 766 condition: it must be terminated immediately.
 767
 768 A _FATAL_-level logging statement should always be followed by
 769 `abort()`.
 770 |
 771 * Unexpected return values from system calls.
 772 * Logic error in internal code, for example an unexpected value in a
 773   `switch` statement.
 774 |Almost none: should be executed in production.
 775
 776 |_ERROR_
 777 |An important error which is somewhat not fatal, that is, the program,
 778 library, or plugin can continue to work after this, but you judge that
 779 it should be reported to the user.
 780
 781 Usually, the program cannot recover from such an error, but it can at
 782 least exit cleanly.
 783 |
 784 * Memory allocation errors.
 785 * Failed to perform an operation which should work considering the
 786   implementation and the satisfied preconditions. For example, the
 787   failure to create an empty object (no parameters): most probably
 788   failed internally because of an allocation error.
 789 * Almost any error in terminal elements: CLI and plugins.
 790 |Almost none: should be executed in production.
 791
 792 |_WARN_
 793 |A logic error which still allows the execution to continue.
 794
 795 _WARN_-level logging statements are for any error or weird action that
 796 is directly or indirectly caused by the user. For example, not having
 797 enough memory is considered beyond the user's control, so we always
 798 log memory errors with an _ERROR_ level (not _FATAL_ because we usually
 799 don't abort in this condition).
 800
 801 Almost all the library's errors are logged as warnings because they are
 802 caused by the user.
 803 |
 804 * Not honoring a public function's preconditions (NULL parameters,
 805   index out of bounds, etc.).
 806 * Adding an invalid event class to a stream class which is already
 807   part of a trace.
 808 +
 809 For example, the caller tries to set a property of a frozen stream
 810 class.
 811 |Almost none: can be executed in production.
 812
 813 |_INFO_
 814 |Any useful information which a non-developer user would understand.
 815 |
 816 * Successful loading of a plugin (with name, version, etc.).
 817 * Successful connection to or disconnection from another system.
 818 * An _optional_ subsystem cannot be loaded.
 819 |Very little: can be executed in production if
 820 _INFO_ level information is desired.
 821
 822 |_DEBUG_
 823 |Something that only Babeltrace developers would be interested into.
 824 |
 825 * High-level function entry/exit.
 826 * Object creation, destruction, copying, and freezing.
 827 * The result of some computation/validation which does not
 828   occur in a tight loop.
 829 |Noticeable, but not as much as the _VERBOSE_ level: not executed in
 830 production.
 831
 832 |_VERBOSE_
 833 |Low-level debugging context information. More appropriate for tracing
 834 in general.
 835 |
 836 * Reference count change.
 837 * Status of each iteration of a loop.
 838 * State machine's state change.
 839 * Data structure lookup/modification.
 840 * List of ELF sections found in a plugin.
 841 * Get or set an object's property.
 842 * Object comparison's intermediate results.
 843 |Huge: not executed in production.
 844 |===
 845
 846 Make sure not to use a _WARN_ (or higher) log level when the condition
 847 leading to the logging statement can occur under normal circumstances.
 848 For example, a public function to get some object or property from an
 849 object by name or key that fails to find the value is not a warning: the
 850 user could legitimately use this function to check if the name/key
 851 exists in the object. In this case, use the _VERBOSE_ level (or do not
 852 log at all). If a numeric index is out of bounds, however, this
 853 qualifies for a _WARN_ level: such API functions have documented
 854 preconditions that the index must be in bounds (the user can always
 855 check with a count or size function).
 856
 857
 858 [[message]]
 859 === Write an appropriate message
 860
 861 Follow those rules when you write a logging statement's message:
 862
 863 * Use an english sentence which starts with a capital letter. Start the
 864   sentence with the appropriate verb tense depending on the context. For
 865   example:
 866 +
 867 --
 868 ** Beginning of operation (present continuous): _Creating ..._,
 869    _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._
 870 ** End of operation (simple past): _Created ..._, _Successfully created ..._,
 871    _Failed to create ..._, _Set ..._ (simple past of _to set_ which is
 872    also _set_)
 873 --
 874 +
 875 For warning and error messages, you can start the message with _Cannot_
 876 or _Failed to_ followed by a verb if it's appropriate.
 877
 878 * Do not include the log level in the message itself. For example,
 879   do not start the message with _Error while_ or _Warning:_.
 880
 881 * Do not put newlines, tabs, or other special characters in the
 882   message, unless you want to log a string with such characters. Note
 883   that multiline log messages can be hard to parse, analyze, and filter,
 884   however, so prefer multiple `BT_LOG*()` statements over a single
 885   statement with newlines.
 886
 887 * **If there are fields that your logging statement must record**,
 888   follow the message with `:` followed by a space, then with the list of
 889   fields (more about this below). If there are no fields, end the
 890   sentence with a period.
 891
 892 The statement's fields _must_ be a comma-separated list of
 893 +__name__=__value__+ tokens. Keep +__name__+ as simple as possible
 894 (lowercase if possible). If +__value__+ is a non-alphanumeric string,
 895 put it between double quotes. Always use the `PRId64` and `PRIu64`
 896 specifiers when logging `int64_t` and `uint64_t` values.
 897
 898 Example:
 899
 900     "Cannot add event class to stream class: stream-class-addr=%p, "
 901     "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", "
 902     "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64
 903
 904 By following a standard format for the statement fields, it is easier
 905 to use tools like https://www.elastic.co/products/logstash[Logstash]
 906 to split fields and analyze logs.
 907
 908 Prefer the following suffixes in field names:
 909
 910 [options="header,autowidth"]
 911 |===
 912 |Field name suffix |Description |Format specifier
 913
 914 |`-addr` |Memory address |`%p`
 915 |`-fd` |File descriptor |`%d`
 916 |`-fp` |File stream (`FILE *`) |`%p`
 917 |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "`
 918 |`-name` |Object's name |`\"%s\"`
 919 |===
 920
 921
 922 === Output
 923
 924 The log is printed to the standard error stream. A log line contains the
 925 time, the process and thread IDs, the <<log-level,log level>>, the
 926 <<choose-a-tag,tag>>, the source's function name, file name and
 927 line number, and the <<message,message>>.
 928
 929 When Babeltrace supports terminal color codes (depends on the
 930 `BABELTRACE_TERM_COLOR` environment variable's value and what the
 931 standard output and error streams are plugged into), _INFO_-level lines
 932 are blue, _WARN_-level lines are yellow, and _ERROR_-level and
 933 _FATAL_-level lines are red.
 934
 935 Log line example:
 936
 937     05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0
 938
 939 You can easily filter the log with `grep` or `ag`. For example, to
 940 keep only the _WARN_-level log messages that the `VALUES` module
 941 generates:
 942
 943     $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE
 944     $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES'