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 itself 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.
73 The API offers the following log levels:
82 See <<level,how to decide which one to use>> below.
84 There are two important log level variables:
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,
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
97 You can set this level at configuration time with the
98 `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example:
102 $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure
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.
110 The library's public API provides `bt_logging_get_minimal_level()` to
111 get the configured minimal log level.
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
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.
132 In libbabeltrace, the user can set the current run-time log level with
133 the `bt_logging_set_global_level()` function, for example:
138 bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO);
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.
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).
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_
159 [[logging-statements]]
160 === Logging statement macros
162 The Babeltrace logging statement macros work just like `printf()` and
163 contain their log level in their name:
165 `BT_LOGV("format string", ...)`::
166 Standard verbose logging statement.
168 `BT_LOGD("format string", ...)`::
169 Standard debug logging statement.
171 `BT_LOGI("format string", ...)`::
172 Standard info logging statement.
174 `BT_LOGW("format string", ...)`::
175 Standard warning logging statement.
177 `BT_LOGE("format string", ...)`::
178 Standard error logging statement.
180 `BT_LOGF("format string", ...)`::
181 Standard fatal logging statement.
183 `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`::
184 Memory verbose logging statement.
186 `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`::
187 Memory debug logging statement.
189 `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`::
190 Memory info logging statement.
192 `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`::
193 Memory warning logging statement.
195 `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`::
196 Memory error logging statement.
198 `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`::
199 Memory fatal logging statement.
201 `BT_LOGV_STR("preformatted string")`::
202 Preformatted string verbose logging statement.
204 `BT_LOGD_STR("preformatted string")`::
205 Preformatted string debug logging statement.
207 `BT_LOGI_STR("preformatted string")`::
208 Preformatted string info logging statement.
210 `BT_LOGW_STR("preformatted string")`::
211 Preformatted string warning logging statement.
213 `BT_LOGE_STR("preformatted string")`::
214 Preformatted string error logging statement.
216 `BT_LOGF_STR("preformatted string")`::
217 Preformatted string fatal logging statement.
220 === Conditional logging
222 `BT_LOG_IF(cond, statement)`::
223 Execute `statement` only if `cond` is true.
230 BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i));
234 To check the <<build-time-log-level,build-time log level>>:
238 #if BT_LOG_ENABLED_DEBUG
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.
248 The available definitions for build-time conditions are:
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`
257 To check the current, <<run-time-log-level,run-time log level>>:
261 if (BT_LOG_ON_DEBUG) {
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.
270 The available definitions for run-time conditions are:
272 * `BT_LOG_ON_VERBOSE`
279 Those macros check the subproject-specific or module-specific log level
280 symbol (defined by `BT_LOG_OUTPUT_LEVEL`).
282 Never, ever write code which would be executed only to compute the
283 fields of a logging statement outside a conditional logging scope,
288 int number = get_number_of_event_classes_with_property_x(...);
289 BT_LOGD("Bla bla: number=%d", number);
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);
306 BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...));
311 === Instrument a module
313 Follow those steps to make your module loggable:
315 . In your module's root directory, create a `logging.c` file with
322 * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
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:
331 * The above copyright notice and this permission notice shall be included in
332 * all copies or substantial portions of the Software.
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
343 #define BT_LOG_OUTPUT_LEVEL my_module_log_level
344 #include <babeltrace/logging-internal.h>
346 BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL");
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.
358 . In your module's root directory, create a `logging.h` file with
364 #ifndef MY_MODULE_LOGGING_H
365 #define MY_MODULE_LOGGING_H
368 * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
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:
377 * The above copyright notice and this permission notice shall be included in
378 * all copies or substantial portions of the Software.
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
389 #define BT_LOG_OUTPUT_LEVEL my_module_log_level
390 #include <babeltrace/logging-internal.h>
392 BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level);
394 #endif /* MY_MODULE_LOGGING_H */
398 Again, replace `my_module_log_level` with the name of your module's
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`.
404 To instrument a C source file (`.c`):
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`:
412 #define BT_LOG_TAG "MY-MODULE-MY-FILE"
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.
423 . Use the <<logging-statements,logging statement macros>> in the file's
424 functions to instrument it.
426 To instrument a C header file (`.h`), if you have `static inline`
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:
438 void some_function(void)
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
466 For plugins, the format of the tag name for a given source file _must_
470 PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__]
476 Component class's name.
479 Component class's type (`SRC`, `FLT`, or `SINK`).
482 Additional information to specify the source file name or module.
486 * `PLUGIN-CTF-LTTNG-LIVE-SRC`
487 * `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER`
488 * `PLUGIN-UTILS-MUXER-FLT`
492 == Choose a log level
494 Choosing the appropriate level for your logging statement is very
497 [options="header,autowidth",cols="default,default,asciidoc,default"]
499 |Log level |Description |Use cases |Impact on performance
502 |The program, library, or plugin cannot continue to work in this
503 condition: it must be terminated immediately.
505 A _FATAL_-level logging statement should always be followed by
508 * Unexpected return values from system calls.
509 * Logic error in internal code, for example an unexpected value in a
511 |Almost none: should be executed in production.
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.
518 Usually, the program cannot recover from such an error, but it can at
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.
530 |A logic error which still allows the execution to continue.
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).
538 Almost all the library's errors are logged as warnings because they are
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
546 For example, the caller tries to set a property of a frozen stream
548 |Almost none: can be executed in production.
551 |Any useful information which a non-developer user would understand.
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.
560 |Something that only Babeltrace developers would be interested into.
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
569 |Low-level debugging context information. More appropriate for tracing
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.
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).
595 == Write an appropriate message
597 Follow those rules when you write a logging statement's message:
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
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
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.
614 * Do not include the log level in the message itself. For example,
615 do not start the message with _Error while_ or _Warning:_.
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.
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.
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.
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
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.
644 Prefer the following suffixes in field names:
646 [options="header,autowidth"]
648 |Field name suffix |Description |Format specifier
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\"`
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
667 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0
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
673 $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE
674 $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES'