| 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' |