1 = Babeltrace logging guide
7 This guide explains to the Babeltrace developer how to insert logging
8 statements in Babeltrace's CLI, library, and plugins.
13 Logging is a great instrument for a developer to be able to collect
14 information about a running software.
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
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.
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.
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.
42 The logging functions are implemented in the logging convenience
43 library (`logging` directory).
48 The logging API headers are:
50 `<babeltrace/logging.h>`::
51 Public header which a library user can use to control and read
52 libbabeltrace's current log level.
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`.
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>`.
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.
72 The API offers the following log levels:
81 See <<level,how to decide which one to use>> below.
83 There are two important log level variables:
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,
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
96 You can set this level at configuration time with the
97 `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example:
101 $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure
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.
109 The library's public API provides `bt_logging_get_minimal_level()` to
110 get the configured minimal log level.
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
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.
131 In libbabeltrace, the user can set the current run-time log level with
132 the `bt_logging_set_global_level()` function, for example:
137 bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO);
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.
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).
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_
158 === Logging statement macros
160 The Babeltrace logging statement macros work just like `printf()` and
161 contain their log level in their name:
163 `BT_LOGV("format string", ...)`::
164 Standard verbose logging statement.
166 `BT_LOGD("format string", ...)`::
167 Standard debug logging statement.
169 `BT_LOGI("format string", ...)`::
170 Standard info logging statement.
172 `BT_LOGW("format string", ...)`::
173 Standard warning logging statement.
175 `BT_LOGE("format string", ...)`::
176 Standard error logging statement.
178 `BT_LOGF("format string", ...)`::
179 Standard fatal logging statement.
181 `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`::
182 Memory verbose logging statement.
184 `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`::
185 Memory debug logging statement.
187 `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`::
188 Memory info logging statement.
190 `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`::
191 Memory warning logging statement.
193 `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`::
194 Memory error logging statement.
196 `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`::
197 Memory fatal logging statement.
199 `BT_LOGV_STR("preformatted string")`::
200 Preformatted string verbose logging statement.
202 `BT_LOGD_STR("preformatted string")`::
203 Preformatted string debug logging statement.
205 `BT_LOGI_STR("preformatted string")`::
206 Preformatted string info logging statement.
208 `BT_LOGW_STR("preformatted string")`::
209 Preformatted string warning logging statement.
211 `BT_LOGE_STR("preformatted string")`::
212 Preformatted string error logging statement.
214 `BT_LOGF_STR("preformatted string")`::
215 Preformatted string fatal logging statement.
218 === Conditional logging
220 `BT_LOG_IF(cond, statement)`::
221 Execute `statement` only if `cond` is true.
228 BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i));
232 To check the <<build-time-log-level,build-time log level>>:
236 #if BT_LOG_ENABLED_DEBUG
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.
246 The available definitions for build-time conditions are:
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`
255 To check the current, <<run-time-log-level,run-time log level>>:
259 if (BT_LOG_ON_DEBUG) {
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.
268 The available definitions for run-time conditions are:
270 * `BT_LOG_ON_VERBOSE`
277 Those macros check the subproject-specific or module-specific log level
278 symbol (defined by `BT_LOG_OUTPUT_LEVEL`).
280 Never, ever write code which would be executed only to compute the
281 fields of a logging statement outside a conditional logging scope,
286 int number = get_number_of_event_classes_with_property_x(...);
287 BT_LOGD("Bla bla: number=%d", number);
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);
304 BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...));
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.
320 #define BT_LOG_TAG "EVENT-CLASS"
321 #include <babeltrace/logging-internal.h>
324 A tag is conceptually similar to a logger name.
329 ==== CTF IR (library)
331 [options="header,autowidth"]
333 |Subsystem/object |Tag name
336 |Clock class and values |`CLOCK-CLASS`
337 |Event class |`EVENT-CLASS`
339 |Field path |`FIELD-PATH`
340 |Field types |`FIELD-TYPES`
344 |Stream class |`STREAM-CLASS`
347 |Validation |`VALIDATION`
352 ==== CTF writer (library)
354 [options="header,autowidth"]
356 |Subsystem/object |Tag name
358 |Clock |`CTF-WRITER-CLOCK`
359 |CTF writer |`CTF-WRITER`
360 |Serialization |`CTF-WRITER-SER`
366 [options="header,autowidth"]
368 |Subsystem/object |Tag name
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`
376 |Notification iterator |`NOTIF-ITER`
378 |Sink component |`COMP-SINK`
379 |Source component |`COMP-SOURCE`
382 ==== Notifications (library)
384 [options="header,autowidth"]
386 |Subsystem/object |Tag name
388 |Event notification |`NOTIF-EVENT`
389 |Inacitivity notification |`NOTIF-INACTIVITY`
390 |Notification |`NOTIF`
391 |Packet notification |`NOTIF-PACKET`
392 |Stream notification |`NOTIF-STREAM`
396 ==== Plugin (library)
398 [options="header,autowidth"]
400 |Subsystem/object |Tag name
403 |Python plugin provider |`PLUGIN-PY`
404 |Shared object plugin provider |`PLUGIN-SO`
408 ==== Values (library)
410 [options="header,autowidth"]
412 |Subsystem/object |Tag name
418 ==== Reference counting (library)
420 [options="header,autowidth"]
422 |Subsystem/object |Tag name
424 |Reference counting |`REF`
428 ==== Common (library)
430 [options="header,autowidth"]
432 |Subsystem/object |Tag name
440 [options="header,autowidth"]
442 |Subsystem/object |Tag name
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`
451 ==== libctfcopytrace (plugin convenience library)
453 [options="header,autowidth"]
455 |Subsystem/object |Tag name
457 |Clock fields |`LIBCTFCOPYTRACE-CLOCK-FIELDS`
458 |libctfcopytrace |`LIBCTFCOPYTRACE`
464 [options="header,autowidth"]
466 |Subsystem/object |Tag name
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`
488 ==== `lttng-utils` plugin
490 [options="header,autowidth"]
492 |Subsystem/object |Tag name
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`
505 [options="header,autowidth"]
507 |Subsystem/object |Tag name
509 |Plugin (main) |`PLUGIN-TEXT`
510 |`pretty` filter (main) |`PLUGIN-TEXT-PRETTY`
511 |`pretty` filter: print |`PLUGIN-TEXT-PRETTY-PRINT`
517 [options="header,autowidth"]
519 |Subsystem/object |Tag name
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`
533 Choosing the appropriate level for your logging statement is very
536 [options="header,autowidth",cols="default,default,asciidoc,default"]
538 |Log level |Description |Use cases |Impact on performance
541 |The program, library, or plugin cannot continue to work in this
542 condition: it must be terminated immediately.
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.
549 * Unexpected return values from system calls.
550 |Almost none: should be executed in production.
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.
557 Usually, the program cannot recover from such an error, but it can at
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.
568 |A logic error which still allows the execution to continue.
570 * Unexpected values for function parameters.
571 * Other user-induced errors (the user does not honor a function's
574 For example, the caller tries to set a property of a frozen stream
576 |Almost none: can be executed in production.
579 |Any useful information which a non-developer user would understand.
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.
588 |Something that only Babeltrace developers would be interested into.
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
597 |Low-level debugging context information. More appropriate for tracing
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.
613 Follow those rules when you write a logging statement's message:
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
621 ** _Created ..._ or _Successfully created ..._
624 For warning and error messages, you can start the message with _Cannot_
625 followed by a verb if it's appropriate.
627 * Do not include the log level in the message itself. For example,
628 do not start the message with _Error while_ or _Warning:_.
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,
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.
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
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
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.
655 Prefer the following suffixes in field names:
657 [options="header,autowidth"]
659 |Field name suffix |Description |Format specifier
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`
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.
678 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0
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
684 $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE
685 $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES'