= Babeltrace logging guide
Philippe Proulx
-7 May 2017
+31 May 2017
:toc:
:toclevels: 5
The Babeltrace logging API is internal: it is not exposed to the users
of the library, only to their developers. The only thing that a library
-user can control is the current log level of the library with
+user can control is the current log level of the library itself with
`bt_logging_set_global_level()` and the initial library's log level with
the `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable.
different <<tag,tag>>, for example.
+
=== Log levels ===
The API offers the following log levels:
by default.
+[[logging-statements]]
=== Logging statement macros
The Babeltrace logging statement macros work just like `printf()` and
----
-[[tag]]
-== Tag
+[[how-to]]
+=== Instrument a module
-Before including `<babeltrace/logging-internal.h>` (or
-`<babeltrace/lib-logging-internal.h>`) in your C source file, define
-`BT_LOG_TAG` to a name which represents your module. The tag name _must_
-be only uppercase letters/digits and the hyphen (`-`) character.
+Follow those steps to make your module loggable:
-For example:
+. In your module's root directory, create a `logging.c` file with
+ this content:
++
+--
+[source,c]
+----
+/*
+ * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#define BT_LOG_OUTPUT_LEVEL my_module_log_level
+#include <babeltrace/logging-internal.h>
+BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL");
+----
+--
++
+Replace `my_module_log_level` with the name of the symbol which holds
+the log level for your module (should be unique amongst all the log level
+symbols of the project). Replace `BABELTRACE_MY_MODULE_LOG_LEVEL` with
+the name of the environment variable from which to initialize your
+module's log level at construction time. `BT_LOG_INIT_LOG_LEVEL()`
+defines both the hidden log level symbol and a constructor which reads
+the environment variable and sets the log level symbol accordingly.
+
+. In your module's root directory, create a `logging.h` file with
+ this content:
++
+--
[source,c]
----
-#define BT_LOG_TAG "EVENT-CLASS"
+#ifndef MY_MODULE_LOGGING_H
+#define MY_MODULE_LOGGING_H
+
+/*
+ * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/>
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+ * SOFTWARE.
+ */
+
+#define BT_LOG_OUTPUT_LEVEL my_module_log_level
#include <babeltrace/logging-internal.h>
+
+BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level);
+
+#endif /* MY_MODULE_LOGGING_H */
+----
+--
++
+Again, replace `my_module_log_level` with the name of your module's
+log level symbol.
+
+. Include the `logging.c` and `logging.h` in the `_SOURCES` variable
+ of your module's object in your module's root `Makefile.am`.
+
+To instrument a C source file (`.c`):
+
+. At the top of the file, before the first `#include` line (if any),
+ define your file's tag name and include the local `logging.h`:
++
+--
+[source,c]
+----
+#define BT_LOG_TAG "MY-MODULE-MY-FILE"
+#include "logging.h"
+----
+--
++
+A logging tag name is a namespace for a specific source file. Its name
+is part of every log message generated by the statements of the file. A
+logging tag name _must_ be only uppercase letters, digits, and the
+hyphen (`-`) character. See <<tags,Babeltrace standard tags>> for
+a list of standard tags.
+
+. Use the <<logging-statements,logging statement macros>> in the file's
+ functions to instrument it.
+
+To instrument a C header file (`.h`), if you have `static inline`
+functions in it:
+
+. Do not include any logging header.
+. Use the <<logging-statements,logging statement macros>> in the file's
+ functions to instrument it, making each of them conditional to the
+ existence of the macro you're using:
++
+--
+[source,c]
----
+static inline
+void some_function(void)
+{
+ /* ... */
+
+#ifdef BT_LOGV
+ BT_LOGV(...);
+#endif
+
+ /* ... */
-A tag is conceptually similar to a logger name.
+#ifdef BT_LOGW_STR
+ BT_LOGW_STR(...);
+#endif
+
+ /* ... */
+}
+----
+--
++
+The C source files which include this header file determine if logging
+is enabled or not for them (if the source file is instrumented itself),
+and the tag of the included header's logging statement is the same as
+the C source file.
-=== Babeltrace tags
+[[tags]]
+=== Babeltrace standard tags
==== CTF IR (library)
|`fs` source: data stream |`PLUGIN-CTF-FS-SRC-DS`
|`fs` source: file |`PLUGIN-CTF-FS-SRC-FILE`
|`fs` source: metadata |`PLUGIN-CTF-FS-SRC-METADATA`
-|`lttng-live` source (main) |`PLUGIN-CTF-LTTNG-LIVE`
-|`lttng-live` source: data stream |`PLUGIN-CTF-LTTNG-LIVE-DS`
-|`lttng-live` source: metadata |`PLUGIN-CTF-LTTNG-LIVE-METADATA`
-|`lttng-live` source: viewer connection |`PLUGIN-CTF-LTTNG-LIVE-VIEWER`
+|`lttng-live` source (main) |`PLUGIN-CTF-LTTNG-LIVE-SRC`
+|`lttng-live` source: data stream |`PLUGIN-CTF-LTTNG-LIVE-SRC-DS`
+|`lttng-live` source: metadata |`PLUGIN-CTF-LTTNG-LIVE-SRC-METADATA`
+|`lttng-live` source: viewer connection |`PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER`
|===
|Subsystem/object |Tag name
|Plugin (main) |`PLUGIN-LTTNG-UTILS`
-|`debug-info` filter (main) |`PLUGIN-LTTNG-UTILS-DBG-INFO`
-|`debug-info` filter: binary info |`PLUGIN-LTTNG-UTILS-DBG-INFO-BIN-INFO`
-|`debug-info` filter: copy |`PLUGIN-LTTNG-UTILS-DBG-INFO-COPY`
-|`debug-info` filter: CRC32 |`PLUGIN-LTTNG-UTILS-DBG-INFO-CRC32`
-|`debug-info` filter: DWARF |`PLUGIN-LTTNG-UTILS-DBG-INFO-DWARF`
+|`debug-info` filter (main) |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT`
+|`debug-info` filter: binary info |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-BIN-INFO`
+|`debug-info` filter: copy |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-COPY`
+|`debug-info` filter: CRC32 |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-CRC32`
+|`debug-info` filter: DWARF |`PLUGIN-LTTNG-UTILS-DBG-INFO-FILT-DWARF`
|===
|Subsystem/object |Tag name
|Plugin (main) |`PLUGIN-TEXT`
-|`pretty` filter (main) |`PLUGIN-TEXT-PRETTY`
-|`pretty` filter: print |`PLUGIN-TEXT-PRETTY-PRINT`
+|`pretty` filter (main) |`PLUGIN-TEXT-PRETTY-SINK`
+|`pretty` filter: print |`PLUGIN-TEXT-PRETTY-SINK-PRINT`
|===
|Subsystem/object |Tag name
|Plugin (main) |`PLUGIN-UTILS`
-|`dummy` sink (main) |`PLUGIN-UTILS-DUMMY`
-|`muxer` filter (main) |`PLUGIN-UTILS-MUXER`
-|`trimmer` filter (main) |`PLUGIN-UTILS-TRIMMER`
-|`trimmer` filter: copy |`PLUGIN-UTILS-TRIMMER-COPY`
-|`trimmer` filter: iterator |`PLUGIN-UTILS-TRIMMER-ITER`
+|`dummy` sink (main) |`PLUGIN-UTILS-DUMMY-SINK`
+|`muxer` filter (main) |`PLUGIN-UTILS-MUXER-FILT`
+|`trimmer` filter (main) |`PLUGIN-UTILS-TRIMMER-FILT`
+|`trimmer` filter: copy |`PLUGIN-UTILS-TRIMMER-FILT-COPY`
+|`trimmer` filter: iterator |`PLUGIN-UTILS-TRIMMER-FILT-ITER`
|===
[[level]]
-== Log level
+== Choose a log level
Choosing the appropriate level for your logging statement is very
important.
|The program, library, or plugin cannot continue to work in this
condition: it must be terminated immediately.
-An assertion is usually an indicator of where you should put a
-_FATAL_-level logging statement. In Babeltrace, however, memory
-allocation errors are usually propagated back to the caller, so they
-belong to the _ERROR_ log level.
+A _FATAL_-level logging statement should always be followed by
+`abort()`.
|
* Unexpected return values from system calls.
+* Logic error in internal code, for example an unexpected value in a
+ `switch` statement.
|Almost none: should be executed in production.
|_ERROR_
|_WARN_
|A logic error which still allows the execution to continue.
+
+_WARN_-level logging statements are for any error or weird action that
+is directly or indirectly caused by the user. For example, not having
+enough memory is considered beyond the user's control, so we always
+log memory errors with an _ERROR_ level (not _FATAL_ because we usually
+don't abort in this condition).
|
-* Unexpected values for function parameters.
-* Other user-induced errors (the user does not honor a function's
- preconditions).
+* Not honoring a public function's preconditions (NULL parameters,
+ index out of bounds, etc.).
+* Adding an invalid event class to a stream class which is already
+ part of a trace.
+
For example, the caller tries to set a property of a frozen stream
class.
|
* Successful loading of a plugin (with name, version, etc.).
* Successful connection to or disconnection from another system.
-* An optional subsystem cannot be loaded.
+* An _optional_ subsystem cannot be loaded.
|Very little: can be executed in production if
_INFO_ level information is desired.
|Huge: not executed in production.
|===
+Make sure not to use a _WARN_ (or higher) log level when the condition
+leading to the logging statement can occur under normal circumstances.
+For example, a public function to get some object or property from an
+object by name or key that fails to find the value is not a warning: the
+user could legitimately use this function to check if the name/key
+exists in the object. In this case, use the _VERBOSE_ level (or do not
+log at all). If a numeric index is out of bounds, however, this
+qualifies for a _WARN_ level: such API functions have documented
+preconditions that the index must be in bounds (the user can always
+check with a count or size function).
+
-== Message
+[[message]]
+== Write an appropriate message
Follow those rules when you write a logging statement's message:
example:
+
--
-** _Creating ..._
-** _Created ..._ or _Successfully created ..._
+** Beginning of operation (present continuous): _Creating ..._,
+ _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._
+** End of operation (simple past): _Created ..._, _Successfully created ..._,
+ _Failed to create ..._, _Set ..._ (simple past of _to set_ which is
+ also _set_)
--
+
For warning and error messages, you can start the message with _Cannot_
-followed by a verb if it's appropriate.
+or _Failed to_ followed by a verb if it's appropriate.
* Do not include the log level in the message itself. For example,
do not start the message with _Error while_ or _Warning:_.
* Do not put newlines, tabs, or other special characters in the
message, unless you want to log a string with such characters. Note
that multiline log messages can be hard to parse, analyze, and filter,
- however.
+ however, so prefer multiple `BT_LOG*()` statements over a single
+ statement with newlines.
* **If there are fields that your logging statement must record**,
follow the message with `:` followed by a space, then with the list of
The statement's fields _must_ be a comma-separated list of
+__name__=__value__+ tokens. Keep +__name__+ as simple as possible
-(lowercase if possible). If +__value__+ is a string, put it between
-double quotes.
+(lowercase if possible). If +__value__+ is a non-alphanumeric string,
+put it between double quotes. Always use the `PRId64` and `PRIu64`
+specifiers when logging `int64_t` and `uint64_t` values.
Example:
"Cannot add event class to stream class: stream-class-addr=%p, "
- "stream-class-name=\"%s\", stream-class-id=%" PRId64
+ "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", "
"event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64
By following a standard format for the statement fields, it is easier
|`-fp` |File stream (`FILE *`) |`%p`
|`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "`
|`-name` |Object's name |`\"%s\"`
-|`-ref-cnt` |Object's reference count |`%u`
|===
== Output
The log is printed to the standard error stream. A log line contains the
-time, the process and thread IDs, the log level, the tag, the source's
-function name, file name and line number, and the message.
+time, the process and thread IDs, the <<level,log level>>, the tag name,
+the source's function name, file name and line number, and the
+<<message,message>>.
Example: