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