= 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
-
-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.
+[[how-to]]
+=== Instrument a module
-For example:
+Follow those steps to make your module loggable:
+. In your module's root directory, create a `logging.c` file with
+ this content:
++
+--
[source,c]
----
-#define BT_LOG_TAG "EVENT-CLASS"
+/*
+ * 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>
-----
-
-A tag is conceptually similar to a logger name.
-
-
-=== Babeltrace tags
-
-==== CTF IR (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Attributes |`ATTRS`
-|Clock class and values |`CLOCK-CLASS`
-|Event class |`EVENT-CLASS`
-|Event |`EVENT`
-|Field path |`FIELD-PATH`
-|Field types |`FIELD-TYPES`
-|Fields |`FIELDS`
-|Packet |`PACKET`
-|Resolver |`RESOLVE`
-|Stream class |`STREAM-CLASS`
-|Stream |`STREAM`
-|Trace |`TRACE`
-|Validation |`VALIDATION`
-|Visitor |`VISITOR`
-|===
-
-
-==== CTF writer (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Clock |`CTF-WRITER-CLOCK`
-|CTF writer |`CTF-WRITER`
-|Serialization |`CTF-WRITER-SER`
-|===
-
-
-==== Graph (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Clock class priority map |`CC-PRIO-MAP`
-|Component (common) |`COMP`
-|Component class |`COMP-CLASS`
-|Connection |`CONNECTION`
-|Filter component |`COMP-FILTER`
-|Graph |`GRAPH`
-|Notification iterator |`NOTIF-ITER`
-|Port |`PORT`
-|Sink component |`COMP-SINK`
-|Source component |`COMP-SOURCE`
-|===
-
-==== Notifications (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Event notification |`NOTIF-EVENT`
-|Inacitivity notification |`NOTIF-INACTIVITY`
-|Notification |`NOTIF`
-|Packet notification |`NOTIF-PACKET`
-|Stream notification |`NOTIF-STREAM`
-|===
-
-
-==== Plugin (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Plugin |`PLUGIN`
-|Python plugin provider |`PLUGIN-PY`
-|Shared object plugin provider |`PLUGIN-SO`
-|===
-
-
-==== Values (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Values |`VALUES`
-|===
-
-
-==== Reference counting (library)
-
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Reference counting |`REF`
-|===
-
-
-==== Common (library)
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Common |`COMMON`
-|===
-
-
-==== CLI
+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]
+----
+#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>
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
+BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level);
-|CLI (main) |`CLI`
-|CLI configuration (common) |`CLI-CFG`
-|CLI configuration from CLI arguments |`CLI-CFG-ARGS`
-|CLI connection configuration from CLI arguments |`CLI-CFG-ARGS-CONNECT`
-|===
+#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`.
-==== libctfcopytrace (plugin convenience library)
+To instrument a C source file (`.c`):
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
+. 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,Choose a tag>> 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)
+{
+ /* ... */
-|Clock fields |`LIBCTFCOPYTRACE-CLOCK-FIELDS`
-|libctfcopytrace |`LIBCTFCOPYTRACE`
-|===
+#ifdef BT_LOGV
+ BT_LOGV(...);
+#endif
+ /* ... */
-==== `ctf` plugin
+#ifdef BT_LOGW_STR
+ BT_LOGW_STR(...);
+#endif
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
-
-|Plugin (main) |`PLUGIN-CTF`
-|Common: BTR |`PLUGIN-CTF-BTR`
-|Common: CTF IR generation metadata visitor |`PLUGIN-CTF-METADATA-IR-VISITOR`
-|Common: Metadata decoder |`PLUGIN-CTF-METADATA-DECODER`
-|Common: Metadata lexer |`PLUGIN-CTF-METADATA-LEXER`
-|Common: Metadata parser |`PLUGIN-CTF-METADATA-PARSER`
-|Common: Notification iterator |`PLUGIN-CTF-NOTIF-ITER`
-|`fs` sink (main) |`PLUGIN-CTF-FS-SINK`
-|`fs` sink: write |`PLUGIN-CTF-FS-SINK-WRITE`
-|`fs` source (main) |`PLUGIN-CTF-FS-SRC`
-|`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`
-|===
+ /* ... */
+}
+----
+--
++
+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.
-==== `lttng-utils` plugin
+[[tags]]
+=== Choose a tag
-[options="header,autowidth"]
-|===
-|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`
-|===
+For plugins, the format of the tag name for a given source file _must_
+be:
+[verse]
+PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__]
-==== `text` plugin
+__PNAME__::
+ Plugin's name.
-[options="header,autowidth"]
-|===
-|Subsystem/object |Tag name
+__CCNAME__::
+ Component class's name.
-|Plugin (main) |`PLUGIN-TEXT`
-|`pretty` filter (main) |`PLUGIN-TEXT-PRETTY`
-|`pretty` filter: print |`PLUGIN-TEXT-PRETTY-PRINT`
-|===
+__CCTYPE__::
+ Component class's type (`SRC`, `FLT`, or `SINK`).
+__FILE__::
+ Additional information to specify the source file name or module.
-==== `utils` plugin
+Examples:
-[options="header,autowidth"]
-|===
-|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`
-|===
+* `PLUGIN-CTF-LTTNG-LIVE-SRC`
+* `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER`
+* `PLUGIN-UTILS-MUXER-FLT`
[[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_
implementation and the satisfied preconditions. For example, the
failure to create an empty object (no parameters): most probably
failed internally because of an allocation error.
+* Almost any error in terminal elements: CLI and plugins.
|Almost none: should be executed in production.
|_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).
+
+Almost all the library's errors are logged as warnings because they are
+caused by the user.
|
-* 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: