cpp-common/bt2c/logging.hpp: remove no-formatting ("str") alternatives

[babeltrace.git] / CONTRIBUTING.adoc

// Render with Asciidoctor

= Babeltrace contributor's guide
Jérémie Galarneau, Philippe Proulx
v0.2, 19 June 2019
:toc:
:toclevels: 5


This is a partial contributor's guide for the
https://babeltrace.org[Babeltrace] project. If you have any
questions that are not answered by this guide, please post them on
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev[Babeltrace's
mailing list].


== Babeltrace library

=== Object reference counting and lifetime

This section covers the rationale behind the design of Babeltrace's
object lifetime management. This applies to the Babeltrace library, as
well as to the CTF writer library (although the public reference
counting functions are not named the same way).

Starting from Babeltrace 2.0, all publicly exposed objects inherit a
common base: `bt_object`. This base provides a number of facilities to
all objects, chief amongst which are lifetime management functions.

The lifetime of some public objects is managed by reference counting. In
this case, the API offers the `+bt_*_get_ref()+` and `+bt_*_put_ref()+`
functions which respectively increment and decrement an object's
reference count.

As far as lifetime management in concerned, Babeltrace makes a clear
distinction between regular objects, which have a single parent, and
root objects, which don't.


==== The problem

Let us consider a problematic case to illustrate the need for this
distinction.

A user of the Babeltrace library creates a trace class, which _has_ a
stream class (the class of a stream) and that stream class, in turn,
_has_ an event class (the class of an event).

Nothing prevents this user from releasing his reference on any one of
these objects in any order. However, all objects in the
__trace--stream class--event class__ hierarchy can be retrieved
from any other.

For instance, the user could discard his reference on both the event
class and the stream class, only keeping a reference on the trace class.
From this trace class reference, stream classes can be enumerated,
providing the user with a new reference to the stream class he discarded
earlier. Event classes can also be enumerated from stream classes,
providing the user with references to the individual event classes.

Conversely, the user could also hold a reference to an event class and
retrieve its parent stream class. The trace class, in turn, can then be
retrieved from the stream class.

This example illustrates what could be interpreted as a circular
reference dependency existing between these objects. Of course, if the
objects in such a scenario were to hold references to each other (in
both directions), we would be in presence of a circular ownership
resulting in a leak of both objects as their reference counts would
never reach zero.

Nonetheless, the API must offer the guarantee that holding a node to any
node of the graph keeps all other reachable nodes alive.


==== The solution

The scheme employed in Babeltrace to break this cycle consists in the
"children" holding _reverse component references_ to their parents. That
is, in the context of the trace IR, that event classes hold a reference
to their parent stream class and stream classes hold a reference to
their parent trace class.

On the other hand, parents hold _claiming aggregation references_ to
their children. A claiming aggregation reference means that the object
being referenced should not be deleted as long as the reference still
exists. In this respect, it can be said that parents truly hold the
ownership of their children, since they control their lifetime.
Conversely, the reference counting mechanism is leveraged by children to
notify parents that no other child indirectly exposes the parent.

When a parented object's reference count reaches zero, it invokes
`+bt_*_put_ref()+` on its parent and does _not_ free itself. However,
from that point, the object depends on its parent to signal the moment
when it can be safely reclaimed.

The invocation of `+bt_*_put_ref()+` by the last children holding a
reference to its parent might trigger a cascade of `+bt_*_put_ref()+`
from child to parent. Eventually, a **root** object is reached. At that
point, if this orphaned object's reference count reaches zero, the
object invokes the destructor method defined by everyone of its children
as part of their base `struct bt_object`. The key point here is that the
cascade of destructor will necessarily originate from the root and
propagate in preorder to the children. These children will propagate the
destruction to their own children before reclaiming their own memory.
This ensures that a node's pointer to its parent is _always_ valid since
the parent has the responsibility of tearing-down their children before
cleaning themselves up.

Assuming a reference to an object is _acquired_ by calling
`+bt_*_get_ref()+` while its reference count is zero, the object
acquires, in turn, a reference on its parent using `+bt_*_get_ref()+`.
At that point, the child can be thought of as having converted its weak
reference to its parent into a regular reference. That is why this
reference is referred to as a _claiming_ aggregation reference.


==== Caveats

This scheme imposes a number of strict rules defining the relation
between objects:

* Objects may only have one parent.
* Objects, beside the root, are only retrievable from their direct
  parent or children.


==== Example

The initial situation is rather simple: **User{nbsp}A** is holding a
reference to a trace class, **TC1**. As per the rules previously
enounced, stream classes **SC1** and **SC2** don't hold a reference to
**TC1** since their own reference counts are zero. The same holds true
for **EC1**, **EC2** and **EC3** with respect to **SC1** and **SC2**.

image::doc/contributing-images/bt-ref01.png[]

In this second step, we can see that **User{nbsp}A** has acquired a
reference on **SC2** through the trace class, **TC1**.

The stream class's reference count transitions from zero to one,
triggering the acquisition of a strong reference on **TC1** from
**SC2**.

Hence, at this point, the trace class's ownership is shared by
**User{nbsp}A** and **SC2**.

image::doc/contributing-images/bt-ref02.png[]

Next, **User{nbsp}A** acquires a reference on the **EC3** event class
through its parent stream class, **SC2**. Again, the transition of an
object's reference count from 0 to 1 triggers the acquisition of a
reference on its parent.

Note that SC2's reference count was incremented to 2. The trace class's
reference count remains unchanged.

image::doc/contributing-images/bt-ref03.png[]

**User{nbsp}A** decides to drop its reference on **SC2**. **SC2**'s
reference count returns back to 1, everything else remaining unchanged.

image::doc/contributing-images/bt-ref04.png[]

**User{nbsp}A** can then decide to drop its reference on the trace
class. This results in a reversal of the initial situation:
**User{nbsp}A** now owns an event, **EC3**, which is keeping everything
else alive and reachable.

image::doc/contributing-images/bt-ref05.png[]

If another object, **User{nbsp}B**, enters the picture and acquires a
reference on the **SC1** stream class, we see that **SC1**'s reference
count transitioned from 0 to 1, triggering the acquisition of a
reference on **TC1**.

image::doc/contributing-images/bt-ref06.png[]

**User{nbsp}B** hands off a reference to **EC1**, acquired through
**SC1**, to another object, **User{nbsp}C**. The acquisition of a
reference on **EC1**, which transitions from 0 to 1, triggers the
acquisition of a reference on its parent, **SC1**.

image::doc/contributing-images/bt-ref07.png[]

At some point, **User{nbsp}A** releases its reference on **EC3**. Since
**EC3**'s reference count transitions to zero, it releases its reference
on **SC2**. **SC2**'s reference count, in turn, reaches zero and it
releases its reference to **TC1**.

**TC1**'s reference count is now 1 and no further action is taken.

image::doc/contributing-images/bt-ref08.png[]

**User{nbsp}B** releases its reference on **SC1**. **User{nbsp}C**
becomes the sole owner of the whole hierarchy through his ownership of
**EC1**.

image::doc/contributing-images/bt-ref09.png[]

Finally, **User{nbsp}C** releases his ownership of **EC1**, triggering
the release of the whole hierarchy. Let's walk through the reclamation
of the whole graph.

Mirroring what happened when **User{nbsp}A** released its last reference
on **EC3**, the release of **EC1** by **User{nbsp}C** causes its
reference count to fall to zero.

This transition to zero causes **EC1** to release its reference on
**SC1**. **SC1**'s reference count reaching zero causes it to release
its reference on **TC1**.

image::doc/contributing-images/bt-ref10.png[]

Since the reference count of **TC1**, a root object, has reached zero,
it invokes the destructor method on its children. This method is
recursive and causes the stream classes to call the destructor method on
their event classes.

The event classes are reached and, having no children of their own, are
reclaimed.

image::doc/contributing-images/bt-ref11.png[]

The stream classes having destroyed their children, are then reclaimed
by the trace class.

image::doc/contributing-images/bt-ref12.png[]

Finally, the stream classes having been reclaimed, **TC1** is reclaimed.

image::doc/contributing-images/bt-ref13.png[]


== Logging

Logging is a great instrument for a developer to be able to collect
information about a running software.

Babeltrace is a complex software with many layers. When a Babeltrace
graph fails to run, what caused the failure? It could be caused by any
component, any message iterator, and any deeply nested validation of a
CTF IR object (within the `ctf` plugin), for example. With the
appropriate logging statements manually placed in the source code, we
can find the cause of a bug faster.

While <<choose-a-log-level,care must be taken>> when placing _DEBUG_ to
_FATAL_ logging statements, you should liberally instrument your
Babeltrace module with _TRACE_ logging statements to help future you
and other developers understand what's happening at run time.


=== Logging API

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 itself with
`bt_logging_set_global_level()` and the initial library's log level with
the `LIBBABELTRACE2_INIT_LOG_LEVEL` environment variable.

This API is based on https://github.com/wonder-mice/zf_log[zf_log], a
lightweight, yet featureful, MIT-licensed core logging library for C and
pass:[C++]. The zf_log source files were modified to have the `BT_` and
`bt_` prefixes, and other small changes, like color support and using
the project's `BT_DEBUG_MODE` definition instead of the standard
`NDEBUG`.

The logging functions are implemented in the logging convenience
library (`src/logging` directory).


[[logging-headers]]
==== Headers

The logging API headers are:

`<babeltrace2/logging.h>`::
    Public header which a library user can use to set and get
    libbabeltrace2's current log level.

`"logging/log.h"`::
    Internal, generic logging API which you can use in any Babeltrace
    module. This is the translation of `zf_log.h`.
+
This header offers the <<gen-logging-statements,generic logging
statement macros>>.

`"lib/logging.h"`::
    Specific internal header to use within the library.
+
This header defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide
hidden symbol which is the library's current log level before including
`"logging/log.h"`.
+
This header offers the <<lib-logging-statements,library-specific logging
statement macros>>.

`"logging/comp-logging.h"`::
    Specific internal header to use within a component class.
+
This header offers the <<comp-logging-statements,component-specific
logging statement macros>>.


[[log-levels]]
==== Log levels

The internal logging API offers the following log levels, in ascending
order of severity:

[options="header,autowidth",cols="4"]
|===
|Log level name
|Log level short name
|Internal API enumerator
|Public API enumerator

|_TRACE_
|`T`
|`BT_LOG_TRACE`
|`BT_LOGGING_LEVEL_TRACE`

|_DEBUG_
|`D`
|`BT_LOG_DEBUG`
|`BT_LOGGING_LEVEL_DEBUG`

|_INFO_
|`I`
|`BT_LOG_INFO`
|`BT_LOGGING_LEVEL_INFO`

|_WARNING_
|`W`
|`BT_LOG_WARNING`
|`BT_LOGGING_LEVEL_WARNING`

|_ERROR_
|`E`
|`BT_LOG_ERROR`
|`BT_LOGGING_LEVEL_ERROR`

|_FATAL_
|`F`
|`BT_LOG_FATAL`
|`BT_LOGGING_LEVEL_FATAL`

|_NONE_
|`N`
|`BT_LOG_NONE`
|`BT_LOGGING_LEVEL_NONE`
|===

The short name is accepted by the log level environment variables and by
the CLI's `--log-level` options.

See <<choose-a-log-level,how to decide which one to use>> below.

There are two important log level expressions:

[[build-time-log-level]]Build-time, minimal log level::
    The minimal log level, or build-time log level, is set at build time
    and determines the minimal log level of the logging statements which
    can be executed. This applies to all the modules (CLI, library,
    plugins, bindings, etc.).
+
All the logging statements with a level below this level are **not built
at all**. All the logging statements with a level equal to or greater
than this level _can_ be executed, depending on the
<<run-time-log-level,run-time log level>>.
+
You can set this level at configuration time with the
`BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example:
+
--
----
$ BABELTRACE_MINIMAL_LOG_LEVEL=INFO ./configure
----
--
+
The default build-time log level is `DEBUG`. For optimal performance,
set it to `INFO`, which effectively disables all fast path logging in
all the Babeltrace modules. You can't set it to `WARNING`, `ERROR`,
`FATAL`, or `NONE` because the impact on performance is minuscule
starting from the _INFO_ log level anyway and we want any Babeltrace
build to always be able to print _INFO_-level logs.
+
The library's public API provides `bt_logging_get_minimal_level()` to
get the configured minimal log level.

[[run-time-log-level]]Run-time, dynamic log level::
    The dynamic log level is set at run time and determines the current,
    _active_ log level. All the logging statements with a level below
    this level are not executed, **but they still evaluate the
    condition**. All the logging statements with a level equal to or
    greater than this level are executed, provided that their level is
    also <<build-time-log-level,enabled at build time>>.
+
`zf_log` has a concept of a global run-time log level which uses the
`_bt_log_global_output_lvl` symbol. In practice, we never use this
symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined to a
module-wise expression before including `"logging/log.h"`.
+
In the library, `"lib/logging.h"` defines its own
`BT_LOG_OUTPUT_LEVEL` to the library's log level symbol before it
includes `"logging/log.h"` itself.
+
In libbabeltrace2, the user can set the current run-time log level with
the `bt_logging_set_global_level()` function, for example:
+
--
[source,c]
----
bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO);
----
--
+
The library's initial run-time log level is defined by the
`LIBBABELTRACE2_INIT_LOG_LEVEL` environment variable, or set to _NONE_
if this environment variable is undefined.
+
Other modules have their own way of setting their run-time log level.
+
For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL` environment
variable, as well as its global `--log-level` option:
+
----
$ babeltrace2 --log-level=I ...
----
+
The components use their own log level (as returned by
`bt_component_get_logging_level()`). With the CLI, you can set a
specific component's log level with its own, position-dependent
`--log-level` option:
+
----
$ babeltrace2 /path/to/trace -c sink.ctf.fs --log-level=D
----
+
Code which is common to the whole project, for example `src/common`
and `src/compat`, use function parameters to get its run-time log
level, for example:
+
[source,c]
----
BT_HIDDEN
char *bt_common_get_home_plugin_path(int log_level);
----
+
Typically, when a logging-enabled module calls such a function, it
passes its own log level expression directly (`BT_LOG_OUTPUT_LEVEL`):
+
[source,c]
----
path = bt_common_get_home_plugin_path(BT_LOG_OUTPUT_LEVEL);
----
+
Otherwise, just pass `BT_LOG_NONE`:
+
----
path = bt_common_get_home_plugin_path(BT_LOG_NONE);
----


[[gen-logging-statements]]
==== Generic logging statement macros

The Babeltrace logging statement macros work just like `printf()`
(except the `+BT_LOG*_STR()+` ones) and contain their <<log-levels,log
level>> (short name) in their name.

Each of the following macros evaluate the
<<build-time-log-level,build-time log level>> definition and
<<run-time-log-level,run-time log level>> expression (as defined by
`BT_LOG_OUTPUT_LEVEL`) to log conditionally.

See <<logging-instrument-c-file-gen,Instrument a C source file
(generic)>> and <<logging-instrument-h-file-gen,Instrument a C header
file (generic)>> to learn how to be able to use the following macros.

`+BT_LOGT("format string", ...)+`::
    Generic trace logging statement.

`+BT_LOGD("format string", ...)+`::
    Generic debug logging statement.

`+BT_LOGI("format string", ...)+`::
    Generic info logging statement.

`+BT_LOGW("format string", ...)+`::
    Generic warning logging statement.

`+BT_LOGE("format string", ...)+`::
    Generic error logging statement.

`+BT_LOGF("format string", ...)+`::
    Generic fatal logging statement.

`+BT_LOGT_STR("preformatted string")+`::
    Generic preformatted string trace logging statement.

`+BT_LOGD_STR("preformatted string")+`::
    Generic preformatted string debug logging statement.

`+BT_LOGI_STR("preformatted string")+`::
    Generic preformatted string info logging statement.

`+BT_LOGW_STR("preformatted string")+`::
    Generic preformatted string warning logging statement.

`+BT_LOGE_STR("preformatted string")+`::
    Generic preformatted string error logging statement.

`+BT_LOGF_STR("preformatted string")+`::
    Generic preformatted string fatal logging statement.

`+BT_LOGT_MEM(data_ptr, data_size, "format string", ...)+`::
    Generic memory trace logging statement.

`+BT_LOGD_MEM(data_ptr, data_size, "format string", ...)+`::
    Generic memory debug logging statement.

`+BT_LOGI_MEM(data_ptr, data_size, "format string", ...)+`::
    Generic memory info logging statement.

`+BT_LOGW_MEM(data_ptr, data_size, "format string", ...)+`::
    Generic memory warning logging statement.

`+BT_LOGE_MEM(data_ptr, data_size, "format string", ...)+`::
    Generic memory error logging statement.

`+BT_LOGF_MEM(data_ptr, data_size, "format string", ...)+`::
    Generic memory fatal logging statement.

`+BT_LOGT_ERRNO("initial message", "format string", ...)+`::
        Generic `errno` string trace logging statement.

`+BT_LOGD_ERRNO("initial message", "format string", ...)+`::
        Generic `errno` string debug logging statement.

`+BT_LOGI_ERRNO("initial message", "format string", ...)+`::
        Generic `errno` string info logging statement.

`+BT_LOGW_ERRNO("initial message", "format string", ...)+`::
        Generic `errno` string warning logging statement.

`+BT_LOGE_ERRNO("initial message", "format string", ...)+`::
        Generic `errno` string error logging statement.

`+BT_LOGF_ERRNO("initial message", "format string", ...)+`::
        Generic `errno` string fatal logging statement.


[[lib-logging-statements]]
==== Library-specific logging statement macros

The Babeltrace library contains an internal logging API based on the
generic logging framework. You can use it to log known Babeltrace
objects without having to manually log each member.

See <<logging-instrument-c-file-lib,Instrument a library C source file>>
and <<logging-instrument-h-file-lib,Instrument a library C header file>> to
learn how to be able to use the following macros.

The library logging statement macros are named `+BT_LIB_LOG*()+` instead
of `+BT_LOG*()+`:

`+BT_LIB_LOGT("format string", ...)+`::
    Library trace logging statement.

`+BT_LIB_LOGD("format string", ...)+`::
    Library debug logging statement.

`+BT_LIB_LOGI("format string", ...)+`::
    Library info logging statement.

`+BT_LIB_LOGW("format string", ...)+`::
    Library warning logging statement.

`+BT_LIB_LOGE("format string", ...)+`::
    Library error logging statement.

`+BT_LIB_LOGF("format string", ...)+`::
    Library fatal logging statement.

`+BT_LIB_LOGW_APPEND_CAUSE("format string", ...)+`::
    Library warning logging statement, and unconditional error cause
    appending.

`+BT_LIB_LOGE_APPEND_CAUSE("format string", ...)+`::
    Library error logging statement, and unconditional error cause
    appending.

`+BT_LIB_LOGF_APPEND_CAUSE("format string", ...)+`::
    Library fatal logging statement, and unconditional error cause
    appending.

The macros above accept the typical `printf()` conversion specifiers
with the following limitations:

* The `+*+` width specifier is not accepted.
* The `+*+` precision specifier is not accepted.
* The `j` and `t` length modifiers are not accepted.
* The `n` format specifier is not accepted.
* The format specifiers defined in `<inttypes.h>` are not accepted,
  except for `PRId64`, `PRIu64`, `PRIx64`, `PRIX64`, `PRIo64`, and
  `PRIi64`.

The Babeltrace library custom conversion specifier is accepted. Its
syntax is either `%!u` to format a UUID (`bt_uuid` type), or:

. Introductory `%!` sequence.

. **Optional**: `[` followed by a custom prefix for the printed fields
  of this specifier, followed by `]`. The standard form is to end this
  prefix with `-` so that, for example, with the prefix `tc-`, the
  complete field name becomes `tc-addr`.

. **Optional**: `pass:[+]` to print extended object members. This
  depends on the provided format specifier.

. Format specifier (see below).

The available format specifiers are:

[options="header,autowidth",cols="3"]
|===
|Specifier
|Object
|Expected C type

|`F`
|Trace IR field class
|`+const struct bt_field_class *+`

|`f`
|Trace IR field
|`+const struct bt_field *+`

|`P`
|Trace IR field path
|`+const struct bt_field_path *+`

|`E`
|Trace IR event class
|`+const struct bt_event_class *+`

|`e`
|Trace IR event
|`+const struct bt_event *+`

|`S`
|Trace IR stream class.
|`+const struct bt_stream_class *+`

|`s`
|Trace IR stream
|`+const struct bt_stream *+`

|`a`
|Trace IR packet
|`+const struct bt_packet *+`

|`T`
|Trace IR trace class
|`+const struct bt_trace_class *+`

|`t`
|Trace IR trace
|`+const struct bt_trace *+`

|`K`
|Trace IR clock class
|`+const struct bt_clock_class *+`

|`k`
|Trace IR clock snapshot
|`+const struct bt_clock_snapshot *+`

|`v`
|Value object
|`+const struct bt_value *+`

|`R`
|Integer range set
|`const struct bt_integer_range_set *`

|`n`
|Message
|`+const struct bt_message *+`

|`I`
|Message iterator class
|`struct bt_message_iterator_class *`

|`i`
|Message iterator
|`struct bt_message_iterator *`

|`C`
|Component class
|`struct bt_component_class *`

|`c`
|Component
|`+const struct bt_component *+`

|`p`
|Port
|`+const struct bt_port *+`

|`x`
|Connection
|`+const struct bt_connection *+`

|`g`
|Graph
|`+const struct bt_graph *+`

|`z`
|Interrupter
|`+struct bt_interrupter *+`

|`l`
|Plugin
|`+const struct bt_plugin *+`

|`r`
|Error cause
|`+const struct bt_error_cause *+`

|`o`
|Object pool
|`+const struct bt_object_pool *+`

|`O`
|Object
|`+const struct bt_object *+`
|===

Conversion specifier examples:

* `%!f`
* `%![my-event-]+e`
* `%!t`
* `%!+F`

The ``, `` string (comma and space) is printed between individual
fields, but **not after the last one**. Therefore, you must put this
separator in the format string between two conversion specifiers, for
example:

[source,c]
----
BT_LIB_LOGW("Message: count=%u, %!E, %!+K", count, event_class, clock_class);
----

Example with a custom prefix:

[source,c]
----
BT_LIB_LOGI("Some message: %![ec-a-]e, %![ec-b-]+e", ec_a, ec_b);
----

It is safe to pass `NULL` as any Babeltrace object parameter: the macros
only print its null address.

WARNING: Build-time `printf()` format checks are disabled for the
`+BT_LIB_LOG*()+` macros because there are custom conversion specifiers,
so make sure to test your logging statements.


[[comp-logging-statements]]
==== Component-specific logging statement macros

There are available logging macros for components. They prepend a prefix
including the component's name to the logging message.

See <<logging-instrument-c-file-compcls,Instrument a component class C
source file>> and <<logging-instrument-h-file-compcls,Instrument a
component class C header file>> to learn how to be able to use the
following macros.

The component logging statement macros are named `+BT_COMP_LOG*()+`
instead of `+BT_LOG*()+`:

`+BT_COMP_LOGT("format string", ...)+`::
    Component trace logging statement.

`+BT_COMP_LOGD("format string", ...)+`::
    Component debug logging statement.

`+BT_COMP_LOGI("format string", ...)+`::
    Component info logging statement.

`+BT_COMP_LOGW("format string", ...)+`::
    Component warning logging statement.

`+BT_COMP_LOGE("format string", ...)+`::
    Component error logging statement.

`+BT_COMP_LOGF("format string", ...)+`::
    Component fatal logging statement.

`+BT_COMP_LOGT_STR("preformatted string")+`::
    Component preformatted string trace logging statement.

`+BT_COMP_LOGD_STR("preformatted string")+`::
    Component preformatted string debug logging statement.

`+BT_COMP_LOGI_STR("preformatted string")+`::
    Component preformatted string info logging statement.

`+BT_COMP_LOGW_STR("preformatted string")+`::
    Component preformatted string warning logging statement.

`+BT_COMP_LOGE_STR("preformatted string")+`::
    Component preformatted string error logging statement.

`+BT_COMP_LOGF_STR("preformatted string")+`::
    Component preformatted string fatal logging statement.

`+BT_COMP_LOGT_ERRNO("initial message", "format string", ...)+`::
    Component `errno` string trace logging statement.

`+BT_COMP_LOGD_ERRNO("initial message", "format string", ...)+`::
    Component `errno` string debug logging statement.

`+BT_COMP_LOGI_ERRNO("initial message", "format string", ...)+`::
    Component `errno` string info logging statement.

`+BT_COMP_LOGW_ERRNO("initial message", "format string", ...)+`::
    Component `errno` string warning logging statement.

`+BT_COMP_LOGE_ERRNO("initial message", "format string", ...)+`::
    Component `errno` string error logging statement.

`+BT_COMP_LOGF_ERRNO("initial message", "format string", ...)+`::
    Component `errno` string fatal logging statement.

`+BT_COMP_LOGT_MEM(data_ptr, data_size, "format string", ...)+`::
    Component memory trace logging statement.

`+BT_COMP_LOGD_MEM(data_ptr, data_size, "format string", ...)+`::
    Component memory debug logging statement.

`+BT_COMP_LOGI_MEM(data_ptr, data_size, "format string", ...)+`::
    Component memory info logging statement.

`+BT_COMP_LOGW_MEM(data_ptr, data_size, "format string", ...)+`::
    Component memory warning logging statement.

`+BT_COMP_LOGE_MEM(data_ptr, data_size, "format string", ...)+`::
    Component memory error logging statement.

`+BT_COMP_LOGF_MEM(data_ptr, data_size, "format string", ...)+`::
    Component memory fatal logging statement.


==== Conditional logging

`+BT_LOG_IF(cond, statement)+`::
    Execute `statement` only if `cond` is true.
+
Example:
+
--
[source,c]
----
BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i));
----
--

To check the <<build-time-log-level,build-time log level>>:

[source,c]
----
#if BT_LOG_ENABLED_DEBUG
...
#endif
----

This tests if the _DEBUG_ level was enabled at build time. This means
that the current, <<run-time-log-level,run-time log level>> _could_ be
_DEBUG_, but it could also be higher. The rule of thumb is to use only
logging statements at the same level in a `BT_LOG_ENABLED_*` conditional
block.

The available definitions for build-time conditions are:

* `BT_LOG_ENABLED_TRACE`
* `BT_LOG_ENABLED_DEBUG`
* `BT_LOG_ENABLED_INFO`
* `BT_LOG_ENABLED_WARNING`
* `BT_LOG_ENABLED_ERROR`
* `BT_LOG_ENABLED_FATAL`

To check the current, <<run-time-log-level,run-time log level>>:

[source,c]
----
if (BT_LOG_ON_DEBUG) {
    ...
}
----

This tests if the _DEBUG_ log level is dynamically turned on
(implies that it's also enabled at build time). This check could have a
noticeable impact on performance.

The available definitions for run-time conditions are:

* `BT_LOG_ON_TRACE`
* `BT_LOG_ON_DEBUG`
* `BT_LOG_ON_INFO`
* `BT_LOG_ON_WARNING`
* `BT_LOG_ON_ERROR`
* `BT_LOG_ON_FATAL`

Those macros check the module-specific log level symbol (defined by
`BT_LOG_OUTPUT_LEVEL`).

Never, ever write code which would be executed only to compute the
fields of a logging statement outside a conditional logging scope,
for example:

[source,c]
----
int number = get_number_of_event_classes_with_property_x(...);
BT_LOGD("Bla bla: number=%d", number);
----

Do this instead:

[source,c]
----
if (BT_LOG_ON_DEBUG) {
    int number = get_number_of_event_classes_with_property_x(...);
    BT_LOGD("Bla bla: number=%d", number);
}
----

Or even this:

[source,c]
----
BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...));
----


=== Guides

[[logging-instrument-c-file-gen]]
==== Instrument a C source file (generic)

To instrument a C source file (`.c`):

. At the top of the file, before the first `#include` line (if any),
  define your file's <<choose-a-logging-tag,logging tag>> name:
+
--
[source,c]
----
#define BT_LOG_TAG "SUBSYS/MY-MODULE/MY-FILE"
----
--

. Below the line above, define the source file's log level expression,
  `BT_LOG_OUTPUT_LEVEL`. This expression is evaluated for each
  <<gen-logging-statements,logging statement>> to know the current
  <<run-time-log-level,run-time log level>>.
+
Examples:
+
[source,c]
----
/* Global log level variable */
#define BT_LOG_OUTPUT_LEVEL module_global_log_level
----
+
[source,c]
----
/* Local log level variable; must exist where you use BT_LOG*() */
#define BT_LOG_OUTPUT_LEVEL log_level
----
+
[source,c]
----
/* Object's log level; `obj` must exist where you use BT_LOG*() */
#define BT_LOG_OUTPUT_LEVEL (obj->log_level)
----

. Include `"logging/log.h"`:
+
[source,c]
----
#include "logging/log.h"
----

. In the file, instrument your code with the
  <<gen-logging-statements,generic logging statement macros>>.


[[logging-instrument-h-file-gen]]
==== Instrument a C header file (generic)

To instrument a C header file (`.h`), if you have `static inline`
functions in it:

. Do not include `"logging/log.h"`!

. Do one of:

.. In the file, instrument your code with the
   <<gen-logging-statements,generic logging statement macros>>, making
   each of them conditional to the existence of the macro you're using:
+
[source,c]
----
static inline
int some_function(int x)
{
    /* ... */

#ifdef BT_LOGT
    BT_LOGT(...);
#endif

    /* ... */

#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, and if so, what is their
<<choose-a-logging-tag,logging tag>> and <<run-time-log-level,run-time
log level>> expression.

.. Require that logging be enabled:
+
[source,c]
----
/* Protection: this file uses BT_LOG*() macros directly */
#ifndef BT_LOG_SUPPORTED
# error Please include "logging/log.h" before including this file.
#endif
----
+
Then, in the file, instrument your code with the
<<gen-logging-statements,generic logging statement macros>>.


[[logging-instrument-c-file-lib]]
==== Instrument a library C source file

To instrument a library C source file (`.c`):

. At the top of the file, before the first `#include` line (if any),
  define your file's <<choose-a-logging-tag,logging tag>> name (this
  tag must start with `LIB/`):
+
--
[source,c]
----
#define BT_LOG_TAG "LIB/THE-FILE"
----
--

. Include `"lib/logging.h"`:
+
[source,c]
----
#include "lib/logging.h"
----

. In the file, instrument your code with the
  <<lib-logging-statements,library logging statement macros>> or with
  the <<gen-logging-statements,generic logging statement macros>>.


[[logging-instrument-h-file-lib]]
==== Instrument a library C header file

To instrument a library C header file (`.h`), if you have `static
inline` functions in it:

. Do not include `"lib/logging.h"`!

. Require that library logging be enabled:
+
[source,c]
----
/* Protection: this file uses BT_LIB_LOG*() macros directly */
#ifndef BT_LIB_LOG_SUPPORTED
# error Please include "lib/logging.h" before including this file.
#endif
----

. In the file, instrument your code with the
  <<lib-logging-statements,library logging statement macros>> or with
  the <<gen-logging-statements,generic logging statement macros>>.


[[logging-instrument-c-file-compcls]]
==== Instrument a component class C source file

To instrument a component class C source file (`.c`):

. At the top of the file, before the first `#include` line (if any),
  define your file's <<choose-a-logging-tag,logging tag>> name (this tag
  must start with `PLUGIN/` followed by the component class identifier):
+
--
[source,c]
----
#define BT_LOG_TAG "PLUGIN/SRC.MY-PLUGIN.MY-SRC"
----
--

. Below the line above, define the source file's log level expression,
  `BT_LOG_OUTPUT_LEVEL`. This expression is evaluated for each
  <<comp-logging-statements,logging statement>> to know the current
  <<run-time-log-level,run-time log level>>.
+
For a component class file, it is usually a member of a local component
private structure variable:
+
[source,c]
----
#define BT_LOG_OUTPUT_LEVEL (my_comp->log_level)
----

. Below the line above, define `BT_COMP_LOG_SELF_COMP` to an expression
  which, evaluated in the context of the
  <<comp-logging-statements,logging statements>>, evaluates to the self
  component address (`+bt_self_component *+`) of the component.
+
This is usually a member of a local component private structure
variable:
+
[source,c]
----
#define BT_COMP_LOG_SELF_COMP (my_comp->self_comp)
----

. Include `"logging/comp-logging.h"`:
+
[source,c]
----
#include "logging/comp-logging.h"
----

. In the component initialization method, make sure to set the
  component private structure's log level member to the initial
  component's log level:
+
[source,c]
----
struct my_comp {
    bt_logging_level log_level;
    /* ... */
};

BT_HIDDEN
bt_self_component_status my_comp_init(
        bt_self_component_source *self_comp_src,
        bt_value *params, void *init_method_data)
{
    struct my_comp *my_comp = g_new0(struct my_comp, 1);
    bt_self_component *self_comp =
        bt_self_component_source_as_self_component(self_comp_src);
    const bt_component *comp = bt_self_component_as_component(self_comp);

    BT_ASSERT(my_comp);
    my_comp->log_level = bt_component_get_logging_level(comp);

    /* ... */
}
----

. In the file, instrument your code with the
  <<comp-logging-statements,component logging statement macros>>.


[[logging-instrument-h-file-compcls]]
==== Instrument a component class C header file

To instrument a component class C header file (`.h`), if you have
`static inline` functions in it:

. Do not include `"logging/comp-logging.h"`!

. Require that component logging be enabled:
+
[source,c]
----
/* Protection: this file uses BT_COMP_LOG*() macros directly */
#ifndef BT_COMP_LOG_SUPPORTED
# error Please include "logging/comp-logging.h" before including this file.
#endif
----

. In the file, instrument your code with the
  <<comp-logging-statements,component logging statement macros>>.


[[choose-a-logging-tag]]
==== Choose a logging tag

Each logging-enabled C source file must define `BT_LOG_TAG` to a logging
tag. A logging tag is a namespace to identify the logging messages of
this specific source file.

In general, a logging tag name _must_ be only uppercase letters, digits,
and the `-`, `.`, and `/` characters.

Use `/` to show the subsystem to source file hierarchy.

For the Babeltrace library, start with `LIB/`.

For the CTF writer library, start with `CTF-WRITER/`.

For component classes, use:

[verse]
`PLUGIN/__CCTYPE__.__PNAME__.__CCNAME__[/__FILE__]`

With:

`__CCTYPE__`::
    Component class's type (`SRC`, `FLT`, or `SINK`).

`__PNAME__`::
    Plugin's name.

`__CCNAME__`::
    Component class's name.

`__FILE__`::
    Additional information to specify the source file name or module.

For plugins (files common to many component classes), use:

[verse]
`PLUGIN/__PNAME__[/__FILE__]`

With:

`__PNAME__`::
    Plugin's name.

`__FILE__`::
    Additional information to specify the source file name or module.


[[choose-a-log-level]]
==== Choose a log level

Choosing the appropriate level for your logging statement is very
important.

[options="header,autowidth",cols="1,2,3a,4"]
|===
|Log level |Description |Use cases |Expected impact on performance

|_FATAL_
|
The program, library, or plugin cannot continue to work in this
condition: it must be terminated immediately.

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.
* Failed assertion (within `BT_ASSERT()`).
* Unsatisfied library precondition (within `BT_ASSERT_PRE()` or
  `BT_ASSERT_PRE_DEV()`).
* Unsatisfied library postcondition (within `BT_ASSERT_POST()` or
  `BT_ASSERT_POST_DEV()`).
|Almost none: always enabled.

|_ERROR_
|
An important error which is somewhat not fatal, that is, the program,
library, or plugin can continue to work after this, but you judge that
it should be reported to the user.

Usually, the program cannot recover from such an error, but it can at
least exit cleanly.
|
* Memory allocation errors.
* Wrong component initialization parameters.
* Corrupted, unrecoverable trace data.
* Failed to perform an operation which should work considering the
  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: always enabled.

|_WARNING_
|
An error which still allows the execution to continue, but you judge
that it should be reported to the user.

_WARNING_-level logging statements are for any error or weird action
that is directly or indirectly caused by the user, often through some
bad input data. 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).
|
* Missing data within something that is expected to have it, but there's
  an alternative.
* Invalid file, but recoverable/fixable.
|Almost none: always enabled.

|_INFO_
|
Any useful information which a non-developer user would possibly
understand.

Anything logged with this level must _not_ happen repetitively on the
fast path, that is, nothing related to each message, for example. This
level is used for sporadic and one-shot events.
|
* CLI or component configuration report.
* Successful plugin, component, or message iterator initialization.
* In the library: anything related to plugins, graphs, component
  classes, components, message iterators, connections, and ports which
  is not on the fast path.
* Successful connection to or disconnection from another system.
* An _optional_ subsystem cannot be loaded.
* An _optional_ field/datum cannot be found.
|
Very little: always enabled.

|_DEBUG_
|
Something that only Babeltrace developers would be interested into,
which can occur on the fast path, but not more often than once per
message.

The _DEBUG_ level is the default <<build-time-log-level,build-time log
level>> as, since it's not _too_ verbose, the performance is similar to
an _INFO_ build.
|
* Object construction and destruction.
* Object recycling (except fields).
* Object copying (except fields and values).
* Object freezing (whatever the type, as freezing only occurs in
  developer mode).
* Object interruption.
* Calling user methods and logging the result.
* Setting object properties (except fields and values).
|
Noticeable, but not as much as the _TRACE_ level: could be executed
in production if you're going to need a thorough log for support
tickets without having to rebuild the project.

|_TRACE_
|
Low-level debugging context information (anything that does not fit the
other log levels). More appropriate for tracing in general.
|
* Reference count change.
* Fast path, low level state machine's state change.
* Get or set an object's property.
* Object comparison's intermediate results.
|Huge: not executed in production.
|===

[IMPORTANT]
--
Make sure not to use a _WARNING_ (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 scenario: the user could legitimately use this function to
check if the name/key exists in the object. In this case, use the
_TRACE_ level (or do not log at all).
--


[[message]]
==== Write an appropriate message

Follow those rules when you write a logging statement's message:

* Use an English sentence which starts with a capital letter.

* Start the sentence with the appropriate verb tense depending on the
  context. For example:
+
--
** 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_
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 logging messages can be hard to parse, analyze, and filter,
  however, so prefer multiple logging 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
  fields (more about this below). If there are no fields, end the
  sentence with a period.

The statement's fields _must_ be a comma-separated list of
`__name__=__value__` tokens. Keep `__name__` as simple as possible; use
kebab case if possible. If `__value__` is a non-alphanumeric string, put
it between double quotes (`"%s"` specifier). Always use the `PRId64` and
`PRIu64` specifiers to log an `int64_t` or an `uint64_t` value. Use `%d`
to log a boolean value.

Example:

    "Cannot read stream data for indexing: path=\"%s\", name=\"%s\", "
    "stream-id=%" PRIu64 ", stream-fd=%d, "
    "index=%" PRIu64 ", status=%s, is-mapped=%d"

By following a standard format for the statement fields, it is easier to
use tools like https://www.elastic.co/products/logstash[Logstash] or
even https://www.splunk.com/[Splunk] to split fields and analyze logs.

Prefer the following suffixes in field names:

[options="header,autowidth"]
|===
|Field name suffix |Description |Format specifier

|`-addr` |Memory address |`%p`
|`-fd` |File descriptor |`%d`
|`-fp` |File stream (`+FILE *+`) |`%p`
|`-id` |Object's ID |`%" PRIu64 "`
|`-index` |Index |`%" PRIu64 "`
|`-name` |Object's name |`\"%s\"`
|===


=== Output

The log is printed to the standard error stream. A log line contains the
time, the process and thread IDs, the <<log-levels,log level>>, the
<<choose-a-logging-tag,logging tag>>, the source's function name, file
name and line number, and the <<message,message>>.

When Babeltrace supports terminal color codes (depends on the
`BABELTRACE_TERM_COLOR` environment variable's value and what the
standard output and error streams are plugged into), _INFO_-level lines
are blue, _WARNING_-level lines are yellow, and _ERROR_-level and
_FATAL_-level lines are red.

Log line example:

----
05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0
----

You can easily filter the log with `grep` or `ag`. For example, to keep
only the _DEBUG_-level logging messages that the `FIELD-CLASS` module
generates:

----
$ babeltrace2 --log-level=D /path/to/trace |& ag 'D FIELD-CLASS'
----


== Valgrind

To use Valgrind on an application (for example, the CLI or a test) which
loads libbabeltrace2, use:

----
$ G_SLICE=always-malloc G_DEBUG=gc-friendly PYTHONMALLOC=malloc \
  LIBBABELTRACE2_NO_DLCLOSE=1 valgrind --leak-check=full app
----

`G_SLICE=always-malloc` and `G_DEBUG=gc-friendly` is for GLib and
`PYTHONMALLOC=malloc` is for the Python interpreter, if it is used by
the Python plugin provider (Valgrind will probably show a lot of errors
which originate from the Python interpreter anyway).

`LIBBABELTRACE2_NO_DLCLOSE=1` makes libbabeltrace2 not close the shared
libraries (plugins) which it loads. You need this to see the appropriate
backtrace when Valgrind shows errors.

== Testing

[[test-env]]
=== Environment

`tests/utils/utils.sh` sets the environment variables for any Babeltrace
test script.

`utils.sh` only needs to know the path to the `tests` directory within
the source and the build directories. By default, `utils.sh` assumes the
build is in tree, that is, you ran `./configure` from the source's root
directory, and sets the `BT_TESTS_SRCDIR` and `BT_TESTS_BUILDDIR`
environment variables accordingly. You can override those variables, for
example if you build out of tree.

All test scripts eventually do something like this to source `utils.sh`,
according to where they are located relative to the `tests` directory:

[source,bash]
----
if [ "x${BT_TESTS_SRCDIR:-}" != "x" ]; then
    UTILSSH="$BT_TESTS_SRCDIR/utils/utils.sh"
else
    UTILSSH="$(dirname "$0")/../utils/utils.sh"
fi
----

==== Python

You can use the `tests/utils/run_python_bt2` script to run any command
within an environment making the build's `bt2` Python package available.

`run_python_bt2` uses <<test-env,`utils.sh`>> which needs to know the
build directory, so make sure you set the `BT_TESTS_BUILDDIR`
environment variable correctly _if you build out of tree_, for example:

----
$ export BT_TESTS_BUILDDIR=/path/to/build/babeltrace/tests
----

You can run any command which needs the `bt2` Python package through
`run_python_bt2`, for example:

----
$ ./tests/utils/run_python_bt2 ipython3
----

=== Report format

All test scripts output the test results following the
https://testanything.org/[Test Anything Protocol] (TAP) format.

The TAP format has two mechanisms to print additional information about
a test:

* Print a line starting with `#` to the standard output.
+
This is usually done with the `diag()` C function or the `diag` shell
function.

* Print to the standard error.


=== Python bindings

The `bt2` Python package tests are located in
`tests/bindings/python/bt2`.


==== Python test runner

`tests/utils/python/testrunner.py` is Babeltrace's Python test runner
which loads Python files containing unit tests, finds all the test
cases, and runs the tests, producing a TAP report.

You can see the test runner command's help with:

----
$ python3 ./tests/utils/python/testrunner.py --help
----

By default, the test runner reports failing tests (TAP's `not{nbsp}ok`
line), but continues to run other tests. You can use the `--failfast`
option to make the test runner fail as soon as a test fails.


==== Guides

To run all the `bt2` Python package tests:

* Run:
+
----
$ ./tests/utils/run_python_bt2 ./tests/bindings/python/bt2/test_python_bt2
----
+
or:
+
----
$ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \
  ./tests/bindings/python/bt2/ -p '*.py'
----

To run **all the tests** in a test module (for example,
`test_value.py`):

* Run:
+
----
$ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \
  ./tests/bindings/python/bt2 -t test_value
----

To run a **specific test case** (for example, `RealValueTestCase` within
`test_value.py`):

* Run:
+
----
$ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \
  ./tests/bindings/python/bt2/ -t test_value.RealValueTestCase
----

To run a **specific test** (for example,
`RealValueTestCase.test_assign_pos_int` within `test_value.py`):

* Run:
+
----
$ ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \
  ./tests/bindings/python/bt2/ -t test_value.RealValueTestCase.test_assign_pos_int
----