doc/logging-guide.adoc

   1 = Babeltrace logging guide
   2 Philippe Proulx
   3 31 May 2017
   4 :toc:
   5 :toclevels: 5
   6
   7 This guide explains to the Babeltrace developer how to insert logging
   8 statements in Babeltrace's CLI, library, and plugins.
   9
  10
  11 == Motive
  12
  13 Logging is a great instrument for a developer to be able to collect
  14 information about a running software.
  15
  16 Babeltrace is a complex software with many layers. When a Babeltrace
  17 graph fails to run, what caused the failure? It could be caused by any
  18 component, any notification iterator, and any deeply nested validation
  19 of a CTR IR object, for example. With the appropriate logging statements
  20 manually placed in the source code, we can find the cause of a bug
  21 faster.
  22
  23 While <<level,care must be taken>> when placing _INFO_ to _FATAL_
  24 logging statements, you should deliberately instrument your Babeltrace
  25 module with _DEBUG_ and _VERBOSE_ logging statements to help future
  26 you and other developers understand what's happening at run-time.
  27
  28
  29 == API
  30
  31 The Babeltrace logging API is internal: it is not exposed to the users
  32 of the library, only to their developers. The only thing that a library
  33 user can control is the current log level of the library itself with
  34 `bt_logging_set_global_level()` and the initial library's log level with
  35 the `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable.
  36
  37 This API is based on https://github.com/wonder-mice/zf_log[zf_log], a
  38 lightweight, yet featureful, MIT-licensed core logging library for C and
  39 $$C++$$. The zf_log source files were modified to have the `BT_` and
  40 `bt_` prefixes, and other small changes.
  41
  42 The logging functions are implemented in the logging convenience
  43 library (`logging` directory).
  44
  45
  46 === Headers
  47
  48 The logging API headers are:
  49
  50 `<babeltrace/logging.h>`::
  51     Public header which a library user can use to control and read
  52     libbabeltrace's current log level.
  53
  54 `<babeltrace/logging-internal.h>`::
  55     Internal, generic logging API which you can use in any Babeltrace
  56     subproject. This is the translation of `zf_log.h`.
  57
  58 `<babeltrace/lib-logging-internal.h>`::
  59     Specific internal header to use within the library. This header
  60     defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide hidden
  61     symbol which is the library's current log level before including
  62     `<babeltrace/logging-internal.h>`.
  63
  64 Do not include `<babeltrace/logging-internal.h>` or
  65 `<babeltrace/lib-logging-internal.h>` in a header which contains logging
  66 statements: this header could be included in source files which define a
  67 different <<tag,tag>>, for example.
  68
  69
  70
  71 === Log levels ===
  72
  73 The API offers the following log levels:
  74
  75 * _VERBOSE_
  76 * _DEBUG_
  77 * _INFO_
  78 * _WARN_
  79 * _ERROR_
  80 * _FATAL_
  81
  82 See <<level,how to decide which one to use>> below.
  83
  84 There are two important log level variables:
  85
  86 [[build-time-log-level]]Build-time, minimal log level::
  87     The minimal log level, or build-time log level, is set at build
  88     time and determines the minimal log level which can be executed.
  89     This applies to all the subprojects and modules (CLI, library,
  90     plugins, etc.).
  91 +
  92 All the logging statements with a level below this level are **not built
  93 at all**. All the logging statements with a level equal to or greater
  94 than this level _can_ be executed, depending on the run-time log level
  95 (see below).
  96 +
  97 You can set this level at configuration time with the
  98 `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example:
  99 +
 100 --
 101 ----
 102 $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure
 103 ----
 104 --
 105 +
 106 The default build-time log level is `DEBUG`. For optimal performance,
 107 set it to `NONE`, which effectively disables all logging in all the
 108 Babeltrace subprojects.
 109 +
 110 The library's public API provides `bt_logging_get_minimal_level()` to
 111 get the configured minimal log level.
 112
 113 [[run-time-log-level]]Run-time, dynamic log level::
 114     The dynamic log level is set at run-time and determines the current,
 115     active log level. All the logging statements with a level below this
 116     level are not executed, but they evaluate the condition. All the
 117     logging statements with a level equal to or greater than this level
 118     are executed, provided that their level is also enabled at build
 119     time (see above).
 120 +
 121 In `zf_log`, there is a concept of a global run-time log level which
 122 uses the `_bt_log_global_output_lvl` symbol. In practice, we never use
 123 this symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined
 124 to a module-wise or subproject-wise hidden symbol before including
 125 `<babeltrace/logging-internal.h>`. In the library,
 126 `<babeltrace/lib-logging-internal.h>` does this job: just include
 127 this header which defines `BT_LOG_OUTPUT_LEVEL` to the appropriate
 128 symbol before it includes `<babeltrace/logging-internal.h>`. In plugins,
 129 for example, there is one log level per component class, which makes
 130 log filtering easier during execution.
 131 +
 132 In libbabeltrace, the user can set the current run-time log level with
 133 the `bt_logging_set_global_level()` function, for example:
 134 +
 135 --
 136 [source,c]
 137 ----
 138 bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO);
 139 ----
 140 --
 141 +
 142 The library's initial run-time log level is defined by the
 143 `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable (`VERBOSE`, `DEBUG`,
 144 `INFO`, `WARN`, `ERROR`, `FATAL`, or `NONE`), or set to _NONE_ if this
 145 environment variable is undefined.
 146 +
 147 Other subprojects have their own way of setting their run-time log
 148 level. For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL`
 149 environment variable, and the `text.pretty` sink component class
 150 initializes its log level thanks to the
 151 `BABELTRACE_PLUGIN_TEXT_PRETTY_SINK_LOG_LEVEL` environment variable
 152 (also _NONE_ by default).
 153 +
 154 Make sure that there is a documented way to initialize or modify the
 155 log level of your subproject or module, and that it's set to _NONE_
 156 by default.
 157
 158
 159 [[logging-statements]]
 160 === Logging statement macros
 161
 162 The Babeltrace logging statement macros work just like `printf()` and
 163 contain their log level in their name:
 164
 165 `BT_LOGV("format string", ...)`::
 166     Standard verbose logging statement.
 167
 168 `BT_LOGD("format string", ...)`::
 169     Standard debug logging statement.
 170
 171 `BT_LOGI("format string", ...)`::
 172     Standard info logging statement.
 173
 174 `BT_LOGW("format string", ...)`::
 175     Standard warning logging statement.
 176
 177 `BT_LOGE("format string", ...)`::
 178     Standard error logging statement.
 179
 180 `BT_LOGF("format string", ...)`::
 181     Standard fatal logging statement.
 182
 183 `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`::
 184     Memory verbose logging statement.
 185
 186 `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`::
 187     Memory debug logging statement.
 188
 189 `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`::
 190     Memory info logging statement.
 191
 192 `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`::
 193     Memory warning logging statement.
 194
 195 `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`::
 196     Memory error logging statement.
 197
 198 `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`::
 199     Memory fatal logging statement.
 200
 201 `BT_LOGV_STR("preformatted string")`::
 202     Preformatted string verbose logging statement.
 203
 204 `BT_LOGD_STR("preformatted string")`::
 205     Preformatted string debug logging statement.
 206
 207 `BT_LOGI_STR("preformatted string")`::
 208     Preformatted string info logging statement.
 209
 210 `BT_LOGW_STR("preformatted string")`::
 211     Preformatted string warning logging statement.
 212
 213 `BT_LOGE_STR("preformatted string")`::
 214     Preformatted string error logging statement.
 215
 216 `BT_LOGF_STR("preformatted string")`::
 217     Preformatted string fatal logging statement.
 218
 219
 220 === Conditional logging
 221
 222 `BT_LOG_IF(cond, statement)`::
 223     Execute `statement` only if `cond` is true.
 224 +
 225 Example:
 226 +
 227 --
 228 [source,c]
 229 ----
 230 BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i));
 231 ----
 232 --
 233
 234 To check the <<build-time-log-level,build-time log level>>:
 235
 236 [source,c]
 237 ----
 238 #if BT_LOG_ENABLED_DEBUG
 239 ...
 240 #endif
 241 ----
 242
 243 This tests if the _DEBUG_ level was enabled at build-time. This
 244 means that the current, dynamic log level _could_ be _DEBUG_, but it
 245 could also be higher. The rule of thumb is to use only logging
 246 statements at the same level in a `BT_LOG_ENABLED_*` conditional block.
 247
 248 The available definitions for build-time conditions are:
 249
 250 * `BT_LOG_ENABLED_VERBOSE`
 251 * `BT_LOG_ENABLED_DEBUG`
 252 * `BT_LOG_ENABLED_INFO`
 253 * `BT_LOG_ENABLED_WARN`
 254 * `BT_LOG_ENABLED_ERROR`
 255 * `BT_LOG_ENABLED_FATAL`
 256
 257 To check the current, <<run-time-log-level,run-time log level>>:
 258
 259 [source,c]
 260 ----
 261 if (BT_LOG_ON_DEBUG) {
 262     ...
 263 }
 264 ----
 265
 266 This tests if the _DEBUG_ log level is dynamically turned on
 267 (implies that it's also enabled at build-time). This check could have a
 268 noticeable impact on performance.
 269
 270 The available definitions for run-time conditions are:
 271
 272 * `BT_LOG_ON_VERBOSE`
 273 * `BT_LOG_ON_DEBUG`
 274 * `BT_LOG_ON_INFO`
 275 * `BT_LOG_ON_WARN`
 276 * `BT_LOG_ON_ERROR`
 277 * `BT_LOG_ON_FATAL`
 278
 279 Those macros check the subproject-specific or module-specific log level
 280 symbol (defined by `BT_LOG_OUTPUT_LEVEL`).
 281
 282 Never, ever write code which would be executed only to compute the
 283 fields of a logging statement outside a conditional logging scope,
 284 for example:
 285
 286 [source,c]
 287 ----
 288 int number = get_number_of_event_classes_with_property_x(...);
 289 BT_LOGD("Bla bla: number=%d", number);
 290 ----
 291
 292 Do this instead:
 293
 294 [source,c]
 295 ----
 296 if (BT_LOG_ON_DEBUG) {
 297     int number = get_number_of_event_classes_with_property_x(...);
 298     BT_LOGD("Bla bla: number=%d", number);
 299 }
 300 ----
 301
 302 Or even this:
 303
 304 [source,c]
 305 ----
 306 BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...));
 307 ----
 308
 309
 310 [[how-to]]
 311 === Instrument a module
 312
 313 Follow those steps to make your module loggable:
 314
 315 . In your module's root directory, create a `logging.c` file with
 316   this content:
 317 +
 318 --
 319 [source,c]
 320 ----
 321 /*
 322  * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
 323  *
 324  * Permission is hereby granted, free of charge, to any person obtaining a copy
 325  * of this software and associated documentation files (the "Software"), to deal
 326  * in the Software without restriction, including without limitation the rights
 327  * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 328  * copies of the Software, and to permit persons to whom the Software is
 329  * furnished to do so, subject to the following conditions:
 330  *
 331  * The above copyright notice and this permission notice shall be included in
 332  * all copies or substantial portions of the Software.
 333  *
 334  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 335  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 336  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 337  * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 338  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 339  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 340  * SOFTWARE.
 341  */
 342
 343 #define BT_LOG_OUTPUT_LEVEL my_module_log_level
 344 #include <babeltrace/logging-internal.h>
 345
 346 BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL");
 347 ----
 348 --
 349 +
 350 Replace `my_module_log_level` with the name of the symbol which holds
 351 the log level for your module (should be unique amongst all the log level
 352 symbols of the project). Replace `BABELTRACE_MY_MODULE_LOG_LEVEL` with
 353 the name of the environment variable from which to initialize your
 354 module's log level at construction time. `BT_LOG_INIT_LOG_LEVEL()`
 355 defines both the hidden log level symbol and a constructor which reads
 356 the environment variable and sets the log level symbol accordingly.
 357
 358 . In your module's root directory, create a `logging.h` file with
 359   this content:
 360 +
 361 --
 362 [source,c]
 363 ----
 364 #ifndef MY_MODULE_LOGGING_H
 365 #define MY_MODULE_LOGGING_H
 366
 367 /*
 368  * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
 369  *
 370  * Permission is hereby granted, free of charge, to any person obtaining a copy
 371  * of this software and associated documentation files (the "Software"), to deal
 372  * in the Software without restriction, including without limitation the rights
 373  * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 374  * copies of the Software, and to permit persons to whom the Software is
 375  * furnished to do so, subject to the following conditions:
 376  *
 377  * The above copyright notice and this permission notice shall be included in
 378  * all copies or substantial portions of the Software.
 379  *
 380  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 381  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 382  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 383  * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 384  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 385  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 386  * SOFTWARE.
 387  */
 388
 389 #define BT_LOG_OUTPUT_LEVEL my_module_log_level
 390 #include <babeltrace/logging-internal.h>
 391
 392 BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level);
 393
 394 #endif /* MY_MODULE_LOGGING_H */
 395 ----
 396 --
 397 +
 398 Again, replace `my_module_log_level` with the name of your module's
 399 log level symbol.
 400
 401 . Include the `logging.c` and `logging.h` in the `_SOURCES` variable
 402   of your module's object in your module's root `Makefile.am`.
 403
 404 To instrument a C source file (`.c`):
 405
 406 . At the top of the file, before the first `#include` line (if any),
 407   define your file's tag name and include the local `logging.h`:
 408 +
 409 --
 410 [source,c]
 411 ----
 412 #define BT_LOG_TAG "MY-MODULE-MY-FILE"
 413 #include "logging.h"
 414 ----
 415 --
 416 +
 417 A logging tag name is a namespace for a specific source file. Its name
 418 is part of every log message generated by the statements of the file. A
 419 logging tag name _must_ be only uppercase letters, digits, and the
 420 hyphen (`-`) character. See <<tags,Babeltrace standard tags>> for
 421 a list of standard tags.
 422
 423 . Use the <<logging-statements,logging statement macros>> in the file's
 424   functions to instrument it.
 425
 426 To instrument a C header file (`.h`), if you have `static inline`
 427 functions in it:
 428
 429 . Do not include any logging header.
 430 . Use the <<logging-statements,logging statement macros>> in the file's
 431   functions to instrument it, making each of them conditional to the
 432   existence of the macro you're using:
 433 +
 434 --
 435 [source,c]
 436 ----
 437 static inline
 438 void some_function(void)
 439 {
 440     /* ... */
 441
 442 #ifdef BT_LOGV
 443     BT_LOGV(...);
 444 #endif
 445
 446     /* ... */
 447
 448 #ifdef BT_LOGW_STR
 449     BT_LOGW_STR(...);
 450 #endif
 451
 452     /* ... */
 453 }
 454 ----
 455 --
 456 +
 457 The C source files which include this header file determine if logging
 458 is enabled or not for them (if the source file is instrumented itself),
 459 and the tag of the included header's logging statement is the same as
 460 the C source file.
 461
 462
 463 [[tags]]
 464 === Babeltrace standard tags
 465
 466 ==== CTF IR (library)
 467
 468 [options="header,autowidth"]
 469 |===
 470 |Subsystem/object |Tag name
 471
 472 |Attributes |`ATTRS`
 473 |Clock class and values |`CLOCK-CLASS`
 474 |Event class |`EVENT-CLASS`
 475 |Event |`EVENT`
 476 |Field path |`FIELD-PATH`
 477 |Field types |`FIELD-TYPES`
 478 |Fields |`FIELDS`
 479 |Packet |`PACKET`
 480 |Resolver |`RESOLVE`
 481 |Stream class |`STREAM-CLASS`
 482 |Stream |`STREAM`
 483 |Trace |`TRACE`
 484 |Validation |`VALIDATION`
 485 |Visitor |`VISITOR`
 486 |===
 487
 488
 489 ==== CTF writer (library)
 490
 491 [options="header,autowidth"]
 492 |===
 493 |Subsystem/object |Tag name
 494
 495 |Clock |`CTF-WRITER-CLOCK`
 496 |CTF writer |`CTF-WRITER`
 497 |Serialization |`CTF-WRITER-SER`
 498 |===
 499
 500
 501 ==== Graph (library)
 502
 503 [options="header,autowidth"]
 504 |===
 505 |Subsystem/object |Tag name
 506
 507 |Clock class priority map |`CC-PRIO-MAP`
 508 |Component (common) |`COMP`
 509 |Component class |`COMP-CLASS`
 510 |Connection |`CONNECTION`
 511 |Filter component |`COMP-FILTER`
 512 |Graph |`GRAPH`
 513 |Notification iterator |`NOTIF-ITER`
 514 |Port |`PORT`
 515 |Sink component |`COMP-SINK`
 516 |Source component |`COMP-SOURCE`
 517 |===
 518
 519 ==== Notifications (library)
 520
 521 [options="header,autowidth"]
 522 |===
 523 |Subsystem/object |Tag name
 524
 525 |Event notification |`NOTIF-EVENT`
 526 |Inacitivity notification |`NOTIF-INACTIVITY`
 527 |Notification |`NOTIF`
 528 |Packet notification |`NOTIF-PACKET`
 529 |Stream notification |`NOTIF-STREAM`
 530 |===
 531
 532
 533 ==== Plugin (library)
 534
 535 [options="header,autowidth"]
 536 |===
 537 |Subsystem/object |Tag name
 538
 539 |Plugin |`PLUGIN`
 540 |Python plugin provider |`PLUGIN-PY`
 541 |Shared object plugin provider |`PLUGIN-SO`
 542 |===
 543
 544
 545 ==== Values (library)
 546
 547 [options="header,autowidth"]
 548 |===
 549 |Subsystem/object |Tag name
 550
 551 |Values |`VALUES`
 552 |===
 553
 554
 555 ==== Reference counting (library)
 556
 557 [options="header,autowidth"]
 558 |===
 559 |Subsystem/object |Tag name
 560
 561 |Reference counting |`REF`
 562 |===
 563
 564
 565 ==== Common (library)
 566
 567 [options="header,autowidth"]
 568 |===
 569 |Subsystem/object |Tag name
 570
 571 |Common |`COMMON`
 572 |===
 573
 574
 575 ==== CLI
 576
 577 [options="header,autowidth"]
 578 |===
 579 |Subsystem/object |Tag name
 580
 581 |CLI (main) |`CLI`
 582 |CLI configuration (common) |`CLI-CFG`
 583 |CLI configuration from CLI arguments |`CLI-CFG-ARGS`
 584 |CLI connection configuration from CLI arguments |`CLI-CFG-ARGS-CONNECT`
 585 |===
 586
 587
 588 ==== libctfcopytrace (plugin convenience library)
 589
 590 [options="header,autowidth"]
 591 |===
 592 |Subsystem/object |Tag name
 593
 594 |Clock fields |`LIBCTFCOPYTRACE-CLOCK-FIELDS`
 595 |libctfcopytrace |`LIBCTFCOPYTRACE`
 596 |===
 597
 598
 599 ==== `ctf` plugin
 600
 601 [options="header,autowidth"]
 602 |===
 603 |Subsystem/object |Tag name
 604
 605 |Plugin (main) |`PLUGIN-CTF`
 606 |Common: BTR |`PLUGIN-CTF-BTR`
 607 |Common: CTF IR generation metadata visitor |`PLUGIN-CTF-METADATA-IR-VISITOR`
 608 |Common: Metadata decoder |`PLUGIN-CTF-METADATA-DECODER`
 609 |Common: Metadata lexer |`PLUGIN-CTF-METADATA-LEXER`
 610 |Common: Metadata parser |`PLUGIN-CTF-METADATA-PARSER`
 611 |Common: Notification iterator |`PLUGIN-CTF-NOTIF-ITER`
 612 |`fs` sink (main) |`PLUGIN-CTF-FS-SINK`
 613 |`fs` sink: write |`PLUGIN-CTF-FS-SINK-WRITE`
 614 |`fs` source (main) |`PLUGIN-CTF-FS-SRC`
 615 |`fs` source: data stream |`PLUGIN-CTF-FS-SRC-DS`
 616 |`fs` source: file |`PLUGIN-CTF-FS-SRC-FILE`
 617 |`fs` source: metadata |`PLUGIN-CTF-FS-SRC-METADATA`
 618 |`lttng-live` source (main) |`PLUGIN-CTF-LTTNG-LIVE-SRC`
 619 |`lttng-live` source: data stream |`PLUGIN-CTF-LTTNG-LIVE-SRC-DS`
 620 |`lttng-live` source: metadata |`PLUGIN-CTF-LTTNG-LIVE-SRC-METADATA`
 621 |`lttng-live` source: viewer connection |`PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER`
 622 |===
 623
 624
 625 ==== `lttng-utils` plugin
 626
 627 [options="header,autowidth"]
 628 |===
 629 |Subsystem/object |Tag name
 630
 631 |Plugin (main) |`PLUGIN-LTTNG-UTILS`
 632 |`debug-info` filter (main) |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT`
 633 |`debug-info` filter: binary info |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-BIN-INFO`
 634 |`debug-info` filter: copy |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-COPY`
 635 |`debug-info` filter: CRC32 |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-CRC32`
 636 |`debug-info` filter: DWARF |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-DWARF`
 637 |===
 638
 639
 640 ==== `text` plugin
 641
 642 [options="header,autowidth"]
 643 |===
 644 |Subsystem/object |Tag name
 645
 646 |Plugin (main) |`PLUGIN-TEXT`
 647 |`pretty` filter (main) |`PLUGIN-TEXT-PRETTY-SINK`
 648 |`pretty` filter: print |`PLUGIN-TEXT-PRETTY-SINK-PRINT`
 649 |===
 650
 651
 652 ==== `utils` plugin
 653
 654 [options="header,autowidth"]
 655 |===
 656 |Subsystem/object |Tag name
 657
 658 |Plugin (main) |`PLUGIN-UTILS`
 659 |`dummy` sink (main) |`PLUGIN-UTILS-DUMMY-SINK`
 660 |`muxer` filter (main) |`PLUGIN-UTILS-MUXER-FILT`
 661 |`trimmer` filter (main) |`PLUGIN-UTILS-TRIMMER-FILT`
 662 |`trimmer` filter: copy |`PLUGIN-UTILS-TRIMMER-FILT-COPY`
 663 |`trimmer` filter: iterator |`PLUGIN-UTILS-TRIMMER-FILT-ITER`
 664 |===
 665
 666
 667 [[level]]
 668 == Choose a log level
 669
 670 Choosing the appropriate level for your logging statement is very
 671 important.
 672
 673 [options="header,autowidth",cols="default,default,asciidoc,default"]
 674 |===
 675 |Log level |Description |Use cases |Impact on performance
 676
 677 |_FATAL_
 678 |The program, library, or plugin cannot continue to work in this
 679 condition: it must be terminated immediately.
 680
 681 A _FATAL_-level logging statement should always be followed by
 682 `abort()`.
 683 |
 684 * Unexpected return values from system calls.
 685 * Logic error in internal code, for example an unexpected value in a
 686   `switch` statement.
 687 |Almost none: should be executed in production.
 688
 689 |_ERROR_
 690 |An important error which is somewhat not fatal, that is, the program,
 691 library, or plugin can continue to work after this, but you judge that
 692 it should be reported to the user.
 693
 694 Usually, the program cannot recover from such an error, but it can at
 695 least exit cleanly.
 696 |
 697 * Memory allocation errors.
 698 * Failed to perform an operation which should work considering the
 699   implementation and the satisfied preconditions. For example, the
 700   failure to create an empty object (no parameters): most probably
 701   failed internally because of an allocation error.
 702 |Almost none: should be executed in production.
 703
 704 |_WARN_
 705 |A logic error which still allows the execution to continue.
 706
 707 _WARN_-level logging statements are for any error or weird action that
 708 is directly or indirectly caused by the user. For example, not having
 709 enough memory is considered beyond the user's control, so we always
 710 log memory errors with an _ERROR_ level (not _FATAL_ because we usually
 711 don't abort in this condition).
 712 |
 713 * Not honoring a public function's preconditions (NULL parameters,
 714   index out of bounds, etc.).
 715 * Adding an invalid event class to a stream class which is already
 716   part of a trace.
 717 +
 718 For example, the caller tries to set a property of a frozen stream
 719 class.
 720 |Almost none: can be executed in production.
 721
 722 |_INFO_
 723 |Any useful information which a non-developer user would understand.
 724 |
 725 * Successful loading of a plugin (with name, version, etc.).
 726 * Successful connection to or disconnection from another system.
 727 * An _optional_ subsystem cannot be loaded.
 728 |Very little: can be executed in production if
 729 _INFO_ level information is desired.
 730
 731 |_DEBUG_
 732 |Something that only Babeltrace developers would be interested into.
 733 |
 734 * High-level function entry/exit.
 735 * Object creation, destruction, copying, and freezing.
 736 * The result of some computation/validation.
 737 |Noticeable, but not as much as the _VERBOSE_ level: not executed in
 738 production.
 739
 740 |_VERBOSE_
 741 |Low-level debugging context information. More appropriate for tracing
 742 in general.
 743 |
 744 * Reference count change.
 745 * Status of each iteration of a loop.
 746 * State machine's state change.
 747 * Data structure lookup/modification.
 748 * List of ELF sections found in a plugin.
 749 * Get or set an object's property.
 750 * Object comparison's intermediate results.
 751 |Huge: not executed in production.
 752 |===
 753
 754 Make sure not to use a _WARN_ (or higher) log level when the condition
 755 leading to the logging statement can occur under normal circumstances.
 756 For example, a public function to get some object or property from an
 757 object by name or key that fails to find the value is not a warning: the
 758 user could legitimately use this function to check if the name/key
 759 exists in the object. In this case, use the _VERBOSE_ level (or do not
 760 log at all). If a numeric index is out of bounds, however, this
 761 qualifies for a _WARN_ level: such API functions have documented
 762 preconditions that the index must be in bounds (the user can always
 763 check with a count or size function).
 764
 765
 766 [[message]]
 767 == Write an appropriate message
 768
 769 Follow those rules when you write a logging statement's message:
 770
 771 * Use an english sentence which starts with a capital letter. Start the
 772   sentence with the appropriate verb tense depending on the context. For
 773   example:
 774 +
 775 --
 776 ** Beginning of operation (present continuous): _Creating ..._,
 777    _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._
 778 ** End of operation (simple past): _Created ..._, _Successfully created ..._,
 779    _Failed to create ..._, _Set ..._ (simple past of _to set_ which is
 780    also _set_)
 781 --
 782 +
 783 For warning and error messages, you can start the message with _Cannot_
 784 or _Failed to_ followed by a verb if it's appropriate.
 785
 786 * Do not include the log level in the message itself. For example,
 787   do not start the message with _Error while_ or _Warning:_.
 788
 789 * Do not put newlines, tabs, or other special characters in the
 790   message, unless you want to log a string with such characters. Note
 791   that multiline log messages can be hard to parse, analyze, and filter,
 792   however, so prefer multiple `BT_LOG*()` statements over a single
 793   statement with newlines.
 794
 795 * **If there are fields that your logging statement must record**,
 796   follow the message with `:` followed by a space, then with the list of
 797   fields (more about this below). If there are no fields, end the
 798   sentence with a period.
 799
 800 The statement's fields _must_ be a comma-separated list of
 801 +__name__=__value__+ tokens. Keep +__name__+ as simple as possible
 802 (lowercase if possible). If +__value__+ is a non-alphanumeric string,
 803 put it between double quotes. Always use the `PRId64` and `PRIu64`
 804 specifiers when logging `int64_t` and `uint64_t` values.
 805
 806 Example:
 807
 808     "Cannot add event class to stream class: stream-class-addr=%p, "
 809     "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", "
 810     "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64
 811
 812 By following a standard format for the statement fields, it is easier
 813 to use tools like https://www.elastic.co/products/logstash[Logstash]
 814 to split fields and analyze logs.
 815
 816 Prefer the following suffixes in field names:
 817
 818 [options="header,autowidth"]
 819 |===
 820 |Field name suffix |Description |Format specifier
 821
 822 |`-addr` |Memory address |`%p`
 823 |`-fd` |File descriptor |`%d`
 824 |`-fp` |File stream (`FILE *`) |`%p`
 825 |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "`
 826 |`-name` |Object's name |`\"%s\"`
 827 |===
 828
 829
 830 == Output
 831
 832 The log is printed to the standard error stream. A log line contains the
 833 time, the process and thread IDs, the <<level,log level>>, the tag name,
 834 the source's function name, file name and line number, and the
 835 <<message,message>>.
 836
 837 Example:
 838
 839     05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0
 840
 841 You can easily filter the log with `grep` or `ag`. For example, to
 842 keep only the _WARN_-level log messages that the `VALUES` module
 843 generates:
 844
 845     $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE
 846     $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES'