| 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,Choose a tag>> 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 | === Choose a tag |
| 465 | |
| 466 | For plugins, the format of the tag name for a given source file _must_ |
| 467 | be: |
| 468 | |
| 469 | [verse] |
| 470 | PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__] |
| 471 | |
| 472 | __PNAME__:: |
| 473 | Plugin's name. |
| 474 | |
| 475 | __CCNAME__:: |
| 476 | Component class's name. |
| 477 | |
| 478 | __CCTYPE__:: |
| 479 | Component class's type (`SRC`, `FLT`, or `SINK`). |
| 480 | |
| 481 | __FILE__:: |
| 482 | Additional information to specify the source file name or module. |
| 483 | |
| 484 | Examples: |
| 485 | |
| 486 | * `PLUGIN-CTF-LTTNG-LIVE-SRC` |
| 487 | * `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER` |
| 488 | * `PLUGIN-UTILS-MUXER-FLT` |
| 489 | |
| 490 | |
| 491 | [[level]] |
| 492 | == Choose a log level |
| 493 | |
| 494 | Choosing the appropriate level for your logging statement is very |
| 495 | important. |
| 496 | |
| 497 | [options="header,autowidth",cols="default,default,asciidoc,default"] |
| 498 | |=== |
| 499 | |Log level |Description |Use cases |Impact on performance |
| 500 | |
| 501 | |_FATAL_ |
| 502 | |The program, library, or plugin cannot continue to work in this |
| 503 | condition: it must be terminated immediately. |
| 504 | |
| 505 | A _FATAL_-level logging statement should always be followed by |
| 506 | `abort()`. |
| 507 | | |
| 508 | * Unexpected return values from system calls. |
| 509 | * Logic error in internal code, for example an unexpected value in a |
| 510 | `switch` statement. |
| 511 | |Almost none: should be executed in production. |
| 512 | |
| 513 | |_ERROR_ |
| 514 | |An important error which is somewhat not fatal, that is, the program, |
| 515 | library, or plugin can continue to work after this, but you judge that |
| 516 | it should be reported to the user. |
| 517 | |
| 518 | Usually, the program cannot recover from such an error, but it can at |
| 519 | least exit cleanly. |
| 520 | | |
| 521 | * Memory allocation errors. |
| 522 | * Failed to perform an operation which should work considering the |
| 523 | implementation and the satisfied preconditions. For example, the |
| 524 | failure to create an empty object (no parameters): most probably |
| 525 | failed internally because of an allocation error. |
| 526 | * Almost any error in terminal elements: CLI and plugins. |
| 527 | |Almost none: should be executed in production. |
| 528 | |
| 529 | |_WARN_ |
| 530 | |A logic error which still allows the execution to continue. |
| 531 | |
| 532 | _WARN_-level logging statements are for any error or weird action that |
| 533 | is directly or indirectly caused by the user. For example, not having |
| 534 | enough memory is considered beyond the user's control, so we always |
| 535 | log memory errors with an _ERROR_ level (not _FATAL_ because we usually |
| 536 | don't abort in this condition). |
| 537 | |
| 538 | Almost all the library's errors are logged as warnings because they are |
| 539 | caused by the user. |
| 540 | | |
| 541 | * Not honoring a public function's preconditions (NULL parameters, |
| 542 | index out of bounds, etc.). |
| 543 | * Adding an invalid event class to a stream class which is already |
| 544 | part of a trace. |
| 545 | + |
| 546 | For example, the caller tries to set a property of a frozen stream |
| 547 | class. |
| 548 | |Almost none: can be executed in production. |
| 549 | |
| 550 | |_INFO_ |
| 551 | |Any useful information which a non-developer user would understand. |
| 552 | | |
| 553 | * Successful loading of a plugin (with name, version, etc.). |
| 554 | * Successful connection to or disconnection from another system. |
| 555 | * An _optional_ subsystem cannot be loaded. |
| 556 | |Very little: can be executed in production if |
| 557 | _INFO_ level information is desired. |
| 558 | |
| 559 | |_DEBUG_ |
| 560 | |Something that only Babeltrace developers would be interested into. |
| 561 | | |
| 562 | * High-level function entry/exit. |
| 563 | * Object creation, destruction, copying, and freezing. |
| 564 | * The result of some computation/validation. |
| 565 | |Noticeable, but not as much as the _VERBOSE_ level: not executed in |
| 566 | production. |
| 567 | |
| 568 | |_VERBOSE_ |
| 569 | |Low-level debugging context information. More appropriate for tracing |
| 570 | in general. |
| 571 | | |
| 572 | * Reference count change. |
| 573 | * Status of each iteration of a loop. |
| 574 | * State machine's state change. |
| 575 | * Data structure lookup/modification. |
| 576 | * List of ELF sections found in a plugin. |
| 577 | * Get or set an object's property. |
| 578 | * Object comparison's intermediate results. |
| 579 | |Huge: not executed in production. |
| 580 | |=== |
| 581 | |
| 582 | Make sure not to use a _WARN_ (or higher) log level when the condition |
| 583 | leading to the logging statement can occur under normal circumstances. |
| 584 | For example, a public function to get some object or property from an |
| 585 | object by name or key that fails to find the value is not a warning: the |
| 586 | user could legitimately use this function to check if the name/key |
| 587 | exists in the object. In this case, use the _VERBOSE_ level (or do not |
| 588 | log at all). If a numeric index is out of bounds, however, this |
| 589 | qualifies for a _WARN_ level: such API functions have documented |
| 590 | preconditions that the index must be in bounds (the user can always |
| 591 | check with a count or size function). |
| 592 | |
| 593 | |
| 594 | [[message]] |
| 595 | == Write an appropriate message |
| 596 | |
| 597 | Follow those rules when you write a logging statement's message: |
| 598 | |
| 599 | * Use an english sentence which starts with a capital letter. Start the |
| 600 | sentence with the appropriate verb tense depending on the context. For |
| 601 | example: |
| 602 | + |
| 603 | -- |
| 604 | ** Beginning of operation (present continuous): _Creating ..._, |
| 605 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ |
| 606 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, |
| 607 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is |
| 608 | also _set_) |
| 609 | -- |
| 610 | + |
| 611 | For warning and error messages, you can start the message with _Cannot_ |
| 612 | or _Failed to_ followed by a verb if it's appropriate. |
| 613 | |
| 614 | * Do not include the log level in the message itself. For example, |
| 615 | do not start the message with _Error while_ or _Warning:_. |
| 616 | |
| 617 | * Do not put newlines, tabs, or other special characters in the |
| 618 | message, unless you want to log a string with such characters. Note |
| 619 | that multiline log messages can be hard to parse, analyze, and filter, |
| 620 | however, so prefer multiple `BT_LOG*()` statements over a single |
| 621 | statement with newlines. |
| 622 | |
| 623 | * **If there are fields that your logging statement must record**, |
| 624 | follow the message with `:` followed by a space, then with the list of |
| 625 | fields (more about this below). If there are no fields, end the |
| 626 | sentence with a period. |
| 627 | |
| 628 | The statement's fields _must_ be a comma-separated list of |
| 629 | +__name__=__value__+ tokens. Keep +__name__+ as simple as possible |
| 630 | (lowercase if possible). If +__value__+ is a non-alphanumeric string, |
| 631 | put it between double quotes. Always use the `PRId64` and `PRIu64` |
| 632 | specifiers when logging `int64_t` and `uint64_t` values. |
| 633 | |
| 634 | Example: |
| 635 | |
| 636 | "Cannot add event class to stream class: stream-class-addr=%p, " |
| 637 | "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " |
| 638 | "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64 |
| 639 | |
| 640 | By following a standard format for the statement fields, it is easier |
| 641 | to use tools like https://www.elastic.co/products/logstash[Logstash] |
| 642 | to split fields and analyze logs. |
| 643 | |
| 644 | Prefer the following suffixes in field names: |
| 645 | |
| 646 | [options="header,autowidth"] |
| 647 | |=== |
| 648 | |Field name suffix |Description |Format specifier |
| 649 | |
| 650 | |`-addr` |Memory address |`%p` |
| 651 | |`-fd` |File descriptor |`%d` |
| 652 | |`-fp` |File stream (`FILE *`) |`%p` |
| 653 | |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "` |
| 654 | |`-name` |Object's name |`\"%s\"` |
| 655 | |=== |
| 656 | |
| 657 | |
| 658 | == Output |
| 659 | |
| 660 | The log is printed to the standard error stream. A log line contains the |
| 661 | time, the process and thread IDs, the <<level,log level>>, the tag name, |
| 662 | the source's function name, file name and line number, and the |
| 663 | <<message,message>>. |
| 664 | |
| 665 | Example: |
| 666 | |
| 667 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 |
| 668 | |
| 669 | You can easily filter the log with `grep` or `ag`. For example, to |
| 670 | keep only the _WARN_-level log messages that the `VALUES` module |
| 671 | generates: |
| 672 | |
| 673 | $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE |
| 674 | $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES' |