X-Git-Url: http://git.efficios.com/?a=blobdiff_plain;f=doc%2Flogging-guide.adoc;h=18a9cfc2b9e043f648c2bf116b820d49e6cd7535;hb=151a8109923ad34382dca7f284ea28887674a848;hp=921188e64ad68ae5f896d20ab9d0b5168c398da8;hpb=beb0fb75663091c20765a8508162711ba828f456;p=babeltrace.git diff --git a/doc/logging-guide.adoc b/doc/logging-guide.adoc index 921188e6..18a9cfc2 100644 --- a/doc/logging-guide.adoc +++ b/doc/logging-guide.adoc @@ -1,6 +1,6 @@ = Babeltrace logging guide Philippe Proulx -7 May 2017 +31 May 2017 :toc: :toclevels: 5 @@ -30,7 +30,7 @@ you and other developers understand what's happening at run-time. 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. @@ -67,6 +67,7 @@ statements: this header could be included in source files which define a different <>, for example. + === Log levels === The API offers the following log levels: @@ -155,6 +156,7 @@ log level of your subproject or module, and that it's set to _NONE_ by default. +[[logging-statements]] === Logging statement macros The Babeltrace logging statement macros work just like `printf()` and @@ -305,26 +307,161 @@ BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); ---- -[[tag]] -== Tag +[[how-to]] +=== Instrument a module -Before including `` (or -``) 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. + * + * 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 +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. + * + * 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 + +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 <> for +a list of standard tags. + +. Use the <> 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 <> 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) @@ -478,10 +615,10 @@ A tag is conceptually similar to a logger name. |`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` |=== @@ -492,11 +629,11 @@ A tag is conceptually similar to a logger name. |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` |=== @@ -507,8 +644,8 @@ A tag is conceptually similar to a logger name. |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` |=== @@ -519,16 +656,16 @@ A tag is conceptually similar to a logger name. |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. @@ -541,12 +678,12 @@ 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_ @@ -566,10 +703,17 @@ least exit cleanly. |_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. @@ -580,7 +724,7 @@ 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. @@ -607,8 +751,20 @@ in general. |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: @@ -617,12 +773,15 @@ 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:_. @@ -630,7 +789,8 @@ followed by a verb if it's appropriate. * 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 @@ -639,13 +799,14 @@ followed by a verb if it's appropriate. 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 @@ -663,15 +824,15 @@ Prefer the following suffixes in field names: |`-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 <>, the tag name, +the source's function name, file name and line number, and the +<>. Example: