| 1 | = Babeltrace logging guide |
| 2 | Philippe Proulx |
| 3 | 7 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 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 statement macros |
| 160 | |
| 161 | The Babeltrace logging statement macros work just like `printf()` and |
| 162 | contain their log level in their name: |
| 163 | |
| 164 | `BT_LOGV("format string", ...)`:: |
| 165 | Standard verbose logging statement. |
| 166 | |
| 167 | `BT_LOGD("format string", ...)`:: |
| 168 | Standard debug logging statement. |
| 169 | |
| 170 | `BT_LOGI("format string", ...)`:: |
| 171 | Standard info logging statement. |
| 172 | |
| 173 | `BT_LOGW("format string", ...)`:: |
| 174 | Standard warning logging statement. |
| 175 | |
| 176 | `BT_LOGE("format string", ...)`:: |
| 177 | Standard error logging statement. |
| 178 | |
| 179 | `BT_LOGF("format string", ...)`:: |
| 180 | Standard fatal logging statement. |
| 181 | |
| 182 | `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`:: |
| 183 | Memory verbose logging statement. |
| 184 | |
| 185 | `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`:: |
| 186 | Memory debug logging statement. |
| 187 | |
| 188 | `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`:: |
| 189 | Memory info logging statement. |
| 190 | |
| 191 | `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`:: |
| 192 | Memory warning logging statement. |
| 193 | |
| 194 | `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`:: |
| 195 | Memory error logging statement. |
| 196 | |
| 197 | `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`:: |
| 198 | Memory fatal logging statement. |
| 199 | |
| 200 | `BT_LOGV_STR("preformatted string")`:: |
| 201 | Preformatted string verbose logging statement. |
| 202 | |
| 203 | `BT_LOGD_STR("preformatted string")`:: |
| 204 | Preformatted string debug logging statement. |
| 205 | |
| 206 | `BT_LOGI_STR("preformatted string")`:: |
| 207 | Preformatted string info logging statement. |
| 208 | |
| 209 | `BT_LOGW_STR("preformatted string")`:: |
| 210 | Preformatted string warning logging statement. |
| 211 | |
| 212 | `BT_LOGE_STR("preformatted string")`:: |
| 213 | Preformatted string error logging statement. |
| 214 | |
| 215 | `BT_LOGF_STR("preformatted string")`:: |
| 216 | Preformatted string fatal logging statement. |
| 217 | |
| 218 | |
| 219 | === Conditional logging |
| 220 | |
| 221 | `BT_LOG_IF(cond, statement)`:: |
| 222 | Execute `statement` only if `cond` is true. |
| 223 | + |
| 224 | Example: |
| 225 | + |
| 226 | -- |
| 227 | [source,c] |
| 228 | ---- |
| 229 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); |
| 230 | ---- |
| 231 | -- |
| 232 | |
| 233 | To check the <<build-time-log-level,build-time log level>>: |
| 234 | |
| 235 | [source,c] |
| 236 | ---- |
| 237 | #if BT_LOG_ENABLED_DEBUG |
| 238 | ... |
| 239 | #endif |
| 240 | ---- |
| 241 | |
| 242 | This tests if the _DEBUG_ level was enabled at build-time. This |
| 243 | means that the current, dynamic log level _could_ be _DEBUG_, but it |
| 244 | could also be higher. The rule of thumb is to use only logging |
| 245 | statements at the same level in a `BT_LOG_ENABLED_*` conditional block. |
| 246 | |
| 247 | The available definitions for build-time conditions are: |
| 248 | |
| 249 | * `BT_LOG_ENABLED_VERBOSE` |
| 250 | * `BT_LOG_ENABLED_DEBUG` |
| 251 | * `BT_LOG_ENABLED_INFO` |
| 252 | * `BT_LOG_ENABLED_WARN` |
| 253 | * `BT_LOG_ENABLED_ERROR` |
| 254 | * `BT_LOG_ENABLED_FATAL` |
| 255 | |
| 256 | To check the current, <<run-time-log-level,run-time log level>>: |
| 257 | |
| 258 | [source,c] |
| 259 | ---- |
| 260 | if (BT_LOG_ON_DEBUG) { |
| 261 | ... |
| 262 | } |
| 263 | ---- |
| 264 | |
| 265 | This tests if the _DEBUG_ log level is dynamically turned on |
| 266 | (implies that it's also enabled at build-time). This check could have a |
| 267 | noticeable impact on performance. |
| 268 | |
| 269 | The available definitions for run-time conditions are: |
| 270 | |
| 271 | * `BT_LOG_ON_VERBOSE` |
| 272 | * `BT_LOG_ON_DEBUG` |
| 273 | * `BT_LOG_ON_INFO` |
| 274 | * `BT_LOG_ON_WARN` |
| 275 | * `BT_LOG_ON_ERROR` |
| 276 | * `BT_LOG_ON_FATAL` |
| 277 | |
| 278 | Those macros check the subproject-specific or module-specific log level |
| 279 | symbol (defined by `BT_LOG_OUTPUT_LEVEL`). |
| 280 | |
| 281 | Never, ever write code which would be executed only to compute the |
| 282 | fields of a logging statement outside a conditional logging scope, |
| 283 | for example: |
| 284 | |
| 285 | [source,c] |
| 286 | ---- |
| 287 | int number = get_number_of_event_classes_with_property_x(...); |
| 288 | BT_LOGD("Bla bla: number=%d", number); |
| 289 | ---- |
| 290 | |
| 291 | Do this instead: |
| 292 | |
| 293 | [source,c] |
| 294 | ---- |
| 295 | if (BT_LOG_ON_DEBUG) { |
| 296 | int number = get_number_of_event_classes_with_property_x(...); |
| 297 | BT_LOGD("Bla bla: number=%d", number); |
| 298 | } |
| 299 | ---- |
| 300 | |
| 301 | Or even this: |
| 302 | |
| 303 | [source,c] |
| 304 | ---- |
| 305 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); |
| 306 | ---- |
| 307 | |
| 308 | |
| 309 | [[tag]] |
| 310 | == Tag |
| 311 | |
| 312 | Before including `<babeltrace/logging-internal.h>` (or |
| 313 | `<babeltrace/lib-logging-internal.h>`) in your C source file, define |
| 314 | `BT_LOG_TAG` to a name which represents your module. The tag name _must_ |
| 315 | be only uppercase letters/digits and the hyphen (`-`) character. |
| 316 | |
| 317 | For example: |
| 318 | |
| 319 | [source,c] |
| 320 | ---- |
| 321 | #define BT_LOG_TAG "EVENT-CLASS" |
| 322 | #include <babeltrace/logging-internal.h> |
| 323 | ---- |
| 324 | |
| 325 | A tag is conceptually similar to a logger name. |
| 326 | |
| 327 | |
| 328 | === Babeltrace tags |
| 329 | |
| 330 | ==== CTF IR (library) |
| 331 | |
| 332 | [options="header,autowidth"] |
| 333 | |=== |
| 334 | |Subsystem/object |Tag name |
| 335 | |
| 336 | |Attributes |`ATTRS` |
| 337 | |Clock class and values |`CLOCK-CLASS` |
| 338 | |Event class |`EVENT-CLASS` |
| 339 | |Event |`EVENT` |
| 340 | |Field path |`FIELD-PATH` |
| 341 | |Field types |`FIELD-TYPES` |
| 342 | |Fields |`FIELDS` |
| 343 | |Packet |`PACKET` |
| 344 | |Resolver |`RESOLVE` |
| 345 | |Stream class |`STREAM-CLASS` |
| 346 | |Stream |`STREAM` |
| 347 | |Trace |`TRACE` |
| 348 | |Validation |`VALIDATION` |
| 349 | |Visitor |`VISITOR` |
| 350 | |=== |
| 351 | |
| 352 | |
| 353 | ==== CTF writer (library) |
| 354 | |
| 355 | [options="header,autowidth"] |
| 356 | |=== |
| 357 | |Subsystem/object |Tag name |
| 358 | |
| 359 | |Clock |`CTF-WRITER-CLOCK` |
| 360 | |CTF writer |`CTF-WRITER` |
| 361 | |Serialization |`CTF-WRITER-SER` |
| 362 | |=== |
| 363 | |
| 364 | |
| 365 | ==== Graph (library) |
| 366 | |
| 367 | [options="header,autowidth"] |
| 368 | |=== |
| 369 | |Subsystem/object |Tag name |
| 370 | |
| 371 | |Clock class priority map |`CC-PRIO-MAP` |
| 372 | |Component (common) |`COMP` |
| 373 | |Component class |`COMP-CLASS` |
| 374 | |Connection |`CONNECTION` |
| 375 | |Filter component |`COMP-FILTER` |
| 376 | |Graph |`GRAPH` |
| 377 | |Notification iterator |`NOTIF-ITER` |
| 378 | |Port |`PORT` |
| 379 | |Sink component |`COMP-SINK` |
| 380 | |Source component |`COMP-SOURCE` |
| 381 | |=== |
| 382 | |
| 383 | ==== Notifications (library) |
| 384 | |
| 385 | [options="header,autowidth"] |
| 386 | |=== |
| 387 | |Subsystem/object |Tag name |
| 388 | |
| 389 | |Event notification |`NOTIF-EVENT` |
| 390 | |Inacitivity notification |`NOTIF-INACTIVITY` |
| 391 | |Notification |`NOTIF` |
| 392 | |Packet notification |`NOTIF-PACKET` |
| 393 | |Stream notification |`NOTIF-STREAM` |
| 394 | |=== |
| 395 | |
| 396 | |
| 397 | ==== Plugin (library) |
| 398 | |
| 399 | [options="header,autowidth"] |
| 400 | |=== |
| 401 | |Subsystem/object |Tag name |
| 402 | |
| 403 | |Plugin |`PLUGIN` |
| 404 | |Python plugin provider |`PLUGIN-PY` |
| 405 | |Shared object plugin provider |`PLUGIN-SO` |
| 406 | |=== |
| 407 | |
| 408 | |
| 409 | ==== Values (library) |
| 410 | |
| 411 | [options="header,autowidth"] |
| 412 | |=== |
| 413 | |Subsystem/object |Tag name |
| 414 | |
| 415 | |Values |`VALUES` |
| 416 | |=== |
| 417 | |
| 418 | |
| 419 | ==== Reference counting (library) |
| 420 | |
| 421 | [options="header,autowidth"] |
| 422 | |=== |
| 423 | |Subsystem/object |Tag name |
| 424 | |
| 425 | |Reference counting |`REF` |
| 426 | |=== |
| 427 | |
| 428 | |
| 429 | ==== Common (library) |
| 430 | |
| 431 | [options="header,autowidth"] |
| 432 | |=== |
| 433 | |Subsystem/object |Tag name |
| 434 | |
| 435 | |Common |`COMMON` |
| 436 | |=== |
| 437 | |
| 438 | |
| 439 | ==== CLI |
| 440 | |
| 441 | [options="header,autowidth"] |
| 442 | |=== |
| 443 | |Subsystem/object |Tag name |
| 444 | |
| 445 | |CLI (main) |`CLI` |
| 446 | |CLI configuration (common) |`CLI-CFG` |
| 447 | |CLI configuration from CLI arguments |`CLI-CFG-ARGS` |
| 448 | |CLI connection configuration from CLI arguments |`CLI-CFG-ARGS-CONNECT` |
| 449 | |=== |
| 450 | |
| 451 | |
| 452 | ==== libctfcopytrace (plugin convenience library) |
| 453 | |
| 454 | [options="header,autowidth"] |
| 455 | |=== |
| 456 | |Subsystem/object |Tag name |
| 457 | |
| 458 | |Clock fields |`LIBCTFCOPYTRACE-CLOCK-FIELDS` |
| 459 | |libctfcopytrace |`LIBCTFCOPYTRACE` |
| 460 | |=== |
| 461 | |
| 462 | |
| 463 | ==== `ctf` plugin |
| 464 | |
| 465 | [options="header,autowidth"] |
| 466 | |=== |
| 467 | |Subsystem/object |Tag name |
| 468 | |
| 469 | |Plugin (main) |`PLUGIN-CTF` |
| 470 | |Common: BTR |`PLUGIN-CTF-BTR` |
| 471 | |Common: CTF IR generation metadata visitor |`PLUGIN-CTF-METADATA-IR-VISITOR` |
| 472 | |Common: Metadata decoder |`PLUGIN-CTF-METADATA-DECODER` |
| 473 | |Common: Metadata lexer |`PLUGIN-CTF-METADATA-LEXER` |
| 474 | |Common: Metadata parser |`PLUGIN-CTF-METADATA-PARSER` |
| 475 | |Common: Notification iterator |`PLUGIN-CTF-NOTIF-ITER` |
| 476 | |`fs` sink (main) |`PLUGIN-CTF-FS-SINK` |
| 477 | |`fs` sink: write |`PLUGIN-CTF-FS-SINK-WRITE` |
| 478 | |`fs` source (main) |`PLUGIN-CTF-FS-SRC` |
| 479 | |`fs` source: data stream |`PLUGIN-CTF-FS-SRC-DS` |
| 480 | |`fs` source: file |`PLUGIN-CTF-FS-SRC-FILE` |
| 481 | |`fs` source: metadata |`PLUGIN-CTF-FS-SRC-METADATA` |
| 482 | |`lttng-live` source (main) |`PLUGIN-CTF-LTTNG-LIVE` |
| 483 | |`lttng-live` source: data stream |`PLUGIN-CTF-LTTNG-LIVE-DS` |
| 484 | |`lttng-live` source: metadata |`PLUGIN-CTF-LTTNG-LIVE-METADATA` |
| 485 | |`lttng-live` source: viewer connection |`PLUGIN-CTF-LTTNG-LIVE-VIEWER` |
| 486 | |=== |
| 487 | |
| 488 | |
| 489 | ==== `lttng-utils` plugin |
| 490 | |
| 491 | [options="header,autowidth"] |
| 492 | |=== |
| 493 | |Subsystem/object |Tag name |
| 494 | |
| 495 | |Plugin (main) |`PLUGIN-LTTNG-UTILS` |
| 496 | |`debug-info` filter (main) |`PLUGIN-LTTNG-UTILS-DBG-INFO` |
| 497 | |`debug-info` filter: binary info |`PLUGIN-LTTNG-UTILS-DBG-INFO-BIN-INFO` |
| 498 | |`debug-info` filter: copy |`PLUGIN-LTTNG-UTILS-DBG-INFO-COPY` |
| 499 | |`debug-info` filter: CRC32 |`PLUGIN-LTTNG-UTILS-DBG-INFO-CRC32` |
| 500 | |`debug-info` filter: DWARF |`PLUGIN-LTTNG-UTILS-DBG-INFO-DWARF` |
| 501 | |=== |
| 502 | |
| 503 | |
| 504 | ==== `text` plugin |
| 505 | |
| 506 | [options="header,autowidth"] |
| 507 | |=== |
| 508 | |Subsystem/object |Tag name |
| 509 | |
| 510 | |Plugin (main) |`PLUGIN-TEXT` |
| 511 | |`pretty` filter (main) |`PLUGIN-TEXT-PRETTY` |
| 512 | |`pretty` filter: print |`PLUGIN-TEXT-PRETTY-PRINT` |
| 513 | |=== |
| 514 | |
| 515 | |
| 516 | ==== `utils` plugin |
| 517 | |
| 518 | [options="header,autowidth"] |
| 519 | |=== |
| 520 | |Subsystem/object |Tag name |
| 521 | |
| 522 | |Plugin (main) |`PLUGIN-UTILS` |
| 523 | |`dummy` sink (main) |`PLUGIN-UTILS-DUMMY` |
| 524 | |`muxer` filter (main) |`PLUGIN-UTILS-MUXER` |
| 525 | |`trimmer` filter (main) |`PLUGIN-UTILS-TRIMMER` |
| 526 | |`trimmer` filter: copy |`PLUGIN-UTILS-TRIMMER-COPY` |
| 527 | |`trimmer` filter: iterator |`PLUGIN-UTILS-TRIMMER-ITER` |
| 528 | |=== |
| 529 | |
| 530 | |
| 531 | [[level]] |
| 532 | == Choose a log level |
| 533 | |
| 534 | Choosing the appropriate level for your logging statement is very |
| 535 | important. |
| 536 | |
| 537 | [options="header,autowidth",cols="default,default,asciidoc,default"] |
| 538 | |=== |
| 539 | |Log level |Description |Use cases |Impact on performance |
| 540 | |
| 541 | |_FATAL_ |
| 542 | |The program, library, or plugin cannot continue to work in this |
| 543 | condition: it must be terminated immediately. |
| 544 | |
| 545 | A _FATAL_-level logging statement should always be followed by |
| 546 | `abort()` or `assert(false)`. |
| 547 | | |
| 548 | * Unexpected return values from system calls. |
| 549 | * Logic error in internal code, for example an unknown value in a |
| 550 | `switch` statement which should only deal with . |
| 551 | |Almost none: should be executed in production. |
| 552 | |
| 553 | |_ERROR_ |
| 554 | |An important error which is somewhat not fatal, that is, the program, |
| 555 | library, or plugin can continue to work after this, but you judge that |
| 556 | it should be reported to the user. |
| 557 | |
| 558 | Usually, the program cannot recover from such an error, but it can at |
| 559 | least exit cleanly. |
| 560 | | |
| 561 | * Memory allocation errors. |
| 562 | * Failed to perform an operation which should work considering the |
| 563 | implementation and the satisfied preconditions. For example, the |
| 564 | failure to create an empty object (no parameters): most probably |
| 565 | failed internally because of an allocation error. |
| 566 | |Almost none: should be executed in production. |
| 567 | |
| 568 | |_WARN_ |
| 569 | |A logic error which still allows the execution to continue. |
| 570 | | |
| 571 | * Unexpected values for function parameters. |
| 572 | * Other user-induced errors (the user does not honor a function's |
| 573 | preconditions). |
| 574 | + |
| 575 | For example, the caller tries to set a property of a frozen stream |
| 576 | class. |
| 577 | |Almost none: can be executed in production. |
| 578 | |
| 579 | |_INFO_ |
| 580 | |Any useful information which a non-developer user would understand. |
| 581 | | |
| 582 | * Successful loading of a plugin (with name, version, etc.). |
| 583 | * Successful connection to or disconnection from another system. |
| 584 | * An optional subsystem cannot be loaded. |
| 585 | |Very little: can be executed in production if |
| 586 | _INFO_ level information is desired. |
| 587 | |
| 588 | |_DEBUG_ |
| 589 | |Something that only Babeltrace developers would be interested into. |
| 590 | | |
| 591 | * High-level function entry/exit. |
| 592 | * Object creation, destruction, copying, and freezing. |
| 593 | * The result of some computation/validation. |
| 594 | |Noticeable, but not as much as the _VERBOSE_ level: not executed in |
| 595 | production. |
| 596 | |
| 597 | |_VERBOSE_ |
| 598 | |Low-level debugging context information. More appropriate for tracing |
| 599 | in general. |
| 600 | | |
| 601 | * Reference count change. |
| 602 | * Status of each iteration of a loop. |
| 603 | * State machine's state change. |
| 604 | * Data structure lookup/modification. |
| 605 | * List of ELF sections found in a plugin. |
| 606 | * Get or set an object's property. |
| 607 | * Object comparison's intermediate results. |
| 608 | |Huge: not executed in production. |
| 609 | |=== |
| 610 | |
| 611 | Make sure not to use a _WARN_ (or higher) log level when the condition |
| 612 | leading to the logging statement can occur under normal circumstances. |
| 613 | For example, a public function to get some object or property from an |
| 614 | object by name or key that fails to find the value is not a warning: the |
| 615 | user could legitimately use this function to check if the name/key |
| 616 | exists in the object. In this case, use the _VERBOSE_ level (or do not |
| 617 | log at all). If a numeric index is out of bounds, however, this |
| 618 | qualifies for a _WARN_ level: such API functions have documented |
| 619 | preconditions that the index must be in bounds (the user can always |
| 620 | check with a count or size function). |
| 621 | |
| 622 | |
| 623 | [[message]] |
| 624 | == Write an appropriate message |
| 625 | |
| 626 | Follow those rules when you write a logging statement's message: |
| 627 | |
| 628 | * Use an english sentence which starts with a capital letter. Start the |
| 629 | sentence with the appropriate verb tense depending on the context. For |
| 630 | example: |
| 631 | + |
| 632 | -- |
| 633 | ** Beginning of operation (present continuous): _Creating ..._, |
| 634 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ |
| 635 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, |
| 636 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is |
| 637 | also _set_) |
| 638 | -- |
| 639 | + |
| 640 | For warning and error messages, you can start the message with _Cannot_ |
| 641 | or _Failed to_ followed by a verb if it's appropriate. |
| 642 | |
| 643 | * Do not include the log level in the message itself. For example, |
| 644 | do not start the message with _Error while_ or _Warning:_. |
| 645 | |
| 646 | * Do not put newlines, tabs, or other special characters in the |
| 647 | message, unless you want to log a string with such characters. Note |
| 648 | that multiline log messages can be hard to parse, analyze, and filter, |
| 649 | however, so prefer multiple `BT_LOG*()` statements over a single |
| 650 | statement with newlines. |
| 651 | |
| 652 | * **If there are fields that your logging statement must record**, |
| 653 | follow the message with `:` followed by a space, then with the list of |
| 654 | fields (more about this below). If there are no fields, end the |
| 655 | sentence with a period. |
| 656 | |
| 657 | The statement's fields _must_ be a comma-separated list of |
| 658 | +__name__=__value__+ tokens. Keep +__name__+ as simple as possible |
| 659 | (lowercase if possible). If +__value__+ is a non-alphanumeric string, |
| 660 | put it between double quotes. Always use the `PRId64` and `PRIu64` |
| 661 | specifiers when logging `int64_t` and `uint64_t` values. |
| 662 | |
| 663 | Example: |
| 664 | |
| 665 | "Cannot add event class to stream class: stream-class-addr=%p, " |
| 666 | "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " |
| 667 | "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64 |
| 668 | |
| 669 | By following a standard format for the statement fields, it is easier |
| 670 | to use tools like https://www.elastic.co/products/logstash[Logstash] |
| 671 | to split fields and analyze logs. |
| 672 | |
| 673 | Prefer the following suffixes in field names: |
| 674 | |
| 675 | [options="header,autowidth"] |
| 676 | |=== |
| 677 | |Field name suffix |Description |Format specifier |
| 678 | |
| 679 | |`-addr` |Memory address |`%p` |
| 680 | |`-fd` |File descriptor |`%d` |
| 681 | |`-fp` |File stream (`FILE *`) |`%p` |
| 682 | |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "` |
| 683 | |`-name` |Object's name |`\"%s\"` |
| 684 | |=== |
| 685 | |
| 686 | |
| 687 | == Output |
| 688 | |
| 689 | The log is printed to the standard error stream. A log line contains the |
| 690 | time, the process and thread IDs, the <<level,log level>>, the <<tag,tag>>, |
| 691 | the source's function name, file name and line number, and the |
| 692 | <<message,message>>. |
| 693 | |
| 694 | Example: |
| 695 | |
| 696 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 |
| 697 | |
| 698 | You can easily filter the log with `grep` or `ag`. For example, to |
| 699 | keep only the _WARN_-level log messages that the `VALUES` module |
| 700 | generates: |
| 701 | |
| 702 | $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE |
| 703 | $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES' |