Commit | Line | Data |
---|---|---|
beb0fb75 PP |
1 | = Babeltrace logging guide |
2 | Philippe Proulx | |
4a41523d | 3 | 31 May 2017 |
beb0fb75 PP |
4 | :toc: |
5 | :toclevels: 5 | |
6 | ||
7 | This guide explains to the Babeltrace developer how to insert logging | |
8 | statements in Babeltrace's CLI, library, and plugins. | |
9 | ||
10 | ||
11 | == Motive | |
12 | ||
13 | Logging is a great instrument for a developer to be able to collect | |
14 | information about a running software. | |
15 | ||
16 | Babeltrace is a complex software with many layers. When a Babeltrace | |
17 | graph fails to run, what caused the failure? It could be caused by any | |
18 | component, any notification iterator, and any deeply nested validation | |
19 | of a CTR IR object, for example. With the appropriate logging statements | |
20 | manually placed in the source code, we can find the cause of a bug | |
21 | faster. | |
22 | ||
23 | While <<level,care must be taken>> when placing _INFO_ to _FATAL_ | |
24 | logging statements, you should deliberately instrument your Babeltrace | |
25 | module with _DEBUG_ and _VERBOSE_ logging statements to help future | |
26 | you and other developers understand what's happening at run-time. | |
27 | ||
28 | ||
29 | == API | |
30 | ||
31 | The Babeltrace logging API is internal: it is not exposed to the users | |
32 | of the library, only to their developers. The only thing that a library | |
4a41523d | 33 | user can control is the current log level of the library itself with |
beb0fb75 PP |
34 | `bt_logging_set_global_level()` and the initial library's log level with |
35 | the `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable. | |
36 | ||
37 | This API is based on https://github.com/wonder-mice/zf_log[zf_log], a | |
38 | lightweight, yet featureful, MIT-licensed core logging library for C and | |
39 | $$C++$$. The zf_log source files were modified to have the `BT_` and | |
40 | `bt_` prefixes, and other small changes. | |
41 | ||
42 | The logging functions are implemented in the logging convenience | |
43 | library (`logging` directory). | |
44 | ||
45 | ||
46 | === Headers | |
47 | ||
48 | The logging API headers are: | |
49 | ||
50 | `<babeltrace/logging.h>`:: | |
51 | Public header which a library user can use to control and read | |
52 | libbabeltrace's current log level. | |
53 | ||
54 | `<babeltrace/logging-internal.h>`:: | |
55 | Internal, generic logging API which you can use in any Babeltrace | |
56 | subproject. This is the translation of `zf_log.h`. | |
57 | ||
58 | `<babeltrace/lib-logging-internal.h>`:: | |
59 | Specific internal header to use within the library. This header | |
60 | defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide hidden | |
61 | symbol which is the library's current log level before including | |
62 | `<babeltrace/logging-internal.h>`. | |
63 | ||
64 | Do not include `<babeltrace/logging-internal.h>` or | |
65 | `<babeltrace/lib-logging-internal.h>` in a header which contains logging | |
66 | statements: this header could be included in source files which define a | |
67 | different <<tag,tag>>, for example. | |
68 | ||
69 | ||
b4b9064d | 70 | |
beb0fb75 PP |
71 | === Log levels === |
72 | ||
73 | The API offers the following log levels: | |
74 | ||
75 | * _VERBOSE_ | |
76 | * _DEBUG_ | |
77 | * _INFO_ | |
78 | * _WARN_ | |
79 | * _ERROR_ | |
80 | * _FATAL_ | |
81 | ||
82 | See <<level,how to decide which one to use>> below. | |
83 | ||
84 | There are two important log level variables: | |
85 | ||
86 | [[build-time-log-level]]Build-time, minimal log level:: | |
87 | The minimal log level, or build-time log level, is set at build | |
88 | time and determines the minimal log level which can be executed. | |
89 | This applies to all the subprojects and modules (CLI, library, | |
90 | plugins, etc.). | |
91 | + | |
92 | All the logging statements with a level below this level are **not built | |
93 | at all**. All the logging statements with a level equal to or greater | |
94 | than this level _can_ be executed, depending on the run-time log level | |
95 | (see below). | |
96 | + | |
97 | You can set this level at configuration time with the | |
98 | `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example: | |
99 | + | |
100 | -- | |
101 | ---- | |
102 | $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure | |
103 | ---- | |
104 | -- | |
105 | + | |
106 | The default build-time log level is `DEBUG`. For optimal performance, | |
107 | set it to `NONE`, which effectively disables all logging in all the | |
108 | Babeltrace subprojects. | |
109 | + | |
110 | The library's public API provides `bt_logging_get_minimal_level()` to | |
111 | get the configured minimal log level. | |
112 | ||
113 | [[run-time-log-level]]Run-time, dynamic log level:: | |
114 | The dynamic log level is set at run-time and determines the current, | |
115 | active log level. All the logging statements with a level below this | |
116 | level are not executed, but they evaluate the condition. All the | |
117 | logging statements with a level equal to or greater than this level | |
118 | are executed, provided that their level is also enabled at build | |
119 | time (see above). | |
120 | + | |
121 | In `zf_log`, there is a concept of a global run-time log level which | |
122 | uses the `_bt_log_global_output_lvl` symbol. In practice, we never use | |
123 | this symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined | |
124 | to a module-wise or subproject-wise hidden symbol before including | |
125 | `<babeltrace/logging-internal.h>`. In the library, | |
126 | `<babeltrace/lib-logging-internal.h>` does this job: just include | |
127 | this header which defines `BT_LOG_OUTPUT_LEVEL` to the appropriate | |
128 | symbol before it includes `<babeltrace/logging-internal.h>`. In plugins, | |
129 | for example, there is one log level per component class, which makes | |
130 | log filtering easier during execution. | |
131 | + | |
132 | In libbabeltrace, the user can set the current run-time log level with | |
133 | the `bt_logging_set_global_level()` function, for example: | |
134 | + | |
135 | -- | |
136 | [source,c] | |
137 | ---- | |
138 | bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO); | |
139 | ---- | |
140 | -- | |
141 | + | |
142 | The library's initial run-time log level is defined by the | |
143 | `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable (`VERBOSE`, `DEBUG`, | |
144 | `INFO`, `WARN`, `ERROR`, `FATAL`, or `NONE`), or set to _NONE_ if this | |
145 | environment variable is undefined. | |
146 | + | |
147 | Other subprojects have their own way of setting their run-time log | |
148 | level. For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL` | |
149 | environment variable, and the `text.pretty` sink component class | |
150 | initializes its log level thanks to the | |
151 | `BABELTRACE_PLUGIN_TEXT_PRETTY_SINK_LOG_LEVEL` environment variable | |
152 | (also _NONE_ by default). | |
153 | + | |
154 | Make sure that there is a documented way to initialize or modify the | |
155 | log level of your subproject or module, and that it's set to _NONE_ | |
156 | by default. | |
157 | ||
158 | ||
4a41523d | 159 | [[logging-statements]] |
beb0fb75 PP |
160 | === Logging statement macros |
161 | ||
162 | The Babeltrace logging statement macros work just like `printf()` and | |
163 | contain their log level in their name: | |
164 | ||
165 | `BT_LOGV("format string", ...)`:: | |
166 | Standard verbose logging statement. | |
167 | ||
168 | `BT_LOGD("format string", ...)`:: | |
169 | Standard debug logging statement. | |
170 | ||
171 | `BT_LOGI("format string", ...)`:: | |
172 | Standard info logging statement. | |
173 | ||
174 | `BT_LOGW("format string", ...)`:: | |
175 | Standard warning logging statement. | |
176 | ||
177 | `BT_LOGE("format string", ...)`:: | |
178 | Standard error logging statement. | |
179 | ||
180 | `BT_LOGF("format string", ...)`:: | |
181 | Standard fatal logging statement. | |
182 | ||
183 | `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`:: | |
184 | Memory verbose logging statement. | |
185 | ||
186 | `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`:: | |
187 | Memory debug logging statement. | |
188 | ||
189 | `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`:: | |
190 | Memory info logging statement. | |
191 | ||
192 | `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`:: | |
193 | Memory warning logging statement. | |
194 | ||
195 | `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`:: | |
196 | Memory error logging statement. | |
197 | ||
198 | `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`:: | |
199 | Memory fatal logging statement. | |
200 | ||
201 | `BT_LOGV_STR("preformatted string")`:: | |
202 | Preformatted string verbose logging statement. | |
203 | ||
204 | `BT_LOGD_STR("preformatted string")`:: | |
205 | Preformatted string debug logging statement. | |
206 | ||
207 | `BT_LOGI_STR("preformatted string")`:: | |
208 | Preformatted string info logging statement. | |
209 | ||
210 | `BT_LOGW_STR("preformatted string")`:: | |
211 | Preformatted string warning logging statement. | |
212 | ||
213 | `BT_LOGE_STR("preformatted string")`:: | |
214 | Preformatted string error logging statement. | |
215 | ||
216 | `BT_LOGF_STR("preformatted string")`:: | |
217 | Preformatted string fatal logging statement. | |
218 | ||
219 | ||
220 | === Conditional logging | |
221 | ||
222 | `BT_LOG_IF(cond, statement)`:: | |
223 | Execute `statement` only if `cond` is true. | |
224 | + | |
225 | Example: | |
226 | + | |
227 | -- | |
228 | [source,c] | |
229 | ---- | |
230 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); | |
231 | ---- | |
232 | -- | |
233 | ||
234 | To check the <<build-time-log-level,build-time log level>>: | |
235 | ||
236 | [source,c] | |
237 | ---- | |
238 | #if BT_LOG_ENABLED_DEBUG | |
239 | ... | |
240 | #endif | |
241 | ---- | |
242 | ||
243 | This tests if the _DEBUG_ level was enabled at build-time. This | |
244 | means that the current, dynamic log level _could_ be _DEBUG_, but it | |
245 | could also be higher. The rule of thumb is to use only logging | |
246 | statements at the same level in a `BT_LOG_ENABLED_*` conditional block. | |
247 | ||
248 | The available definitions for build-time conditions are: | |
249 | ||
250 | * `BT_LOG_ENABLED_VERBOSE` | |
251 | * `BT_LOG_ENABLED_DEBUG` | |
252 | * `BT_LOG_ENABLED_INFO` | |
253 | * `BT_LOG_ENABLED_WARN` | |
254 | * `BT_LOG_ENABLED_ERROR` | |
255 | * `BT_LOG_ENABLED_FATAL` | |
256 | ||
257 | To check the current, <<run-time-log-level,run-time log level>>: | |
258 | ||
259 | [source,c] | |
260 | ---- | |
261 | if (BT_LOG_ON_DEBUG) { | |
262 | ... | |
263 | } | |
264 | ---- | |
265 | ||
266 | This tests if the _DEBUG_ log level is dynamically turned on | |
267 | (implies that it's also enabled at build-time). This check could have a | |
268 | noticeable impact on performance. | |
269 | ||
270 | The available definitions for run-time conditions are: | |
271 | ||
272 | * `BT_LOG_ON_VERBOSE` | |
273 | * `BT_LOG_ON_DEBUG` | |
274 | * `BT_LOG_ON_INFO` | |
275 | * `BT_LOG_ON_WARN` | |
276 | * `BT_LOG_ON_ERROR` | |
277 | * `BT_LOG_ON_FATAL` | |
278 | ||
279 | Those macros check the subproject-specific or module-specific log level | |
280 | symbol (defined by `BT_LOG_OUTPUT_LEVEL`). | |
281 | ||
282 | Never, ever write code which would be executed only to compute the | |
283 | fields of a logging statement outside a conditional logging scope, | |
284 | for example: | |
285 | ||
286 | [source,c] | |
287 | ---- | |
288 | int number = get_number_of_event_classes_with_property_x(...); | |
289 | BT_LOGD("Bla bla: number=%d", number); | |
290 | ---- | |
291 | ||
292 | Do this instead: | |
293 | ||
294 | [source,c] | |
295 | ---- | |
296 | if (BT_LOG_ON_DEBUG) { | |
297 | int number = get_number_of_event_classes_with_property_x(...); | |
298 | BT_LOGD("Bla bla: number=%d", number); | |
299 | } | |
300 | ---- | |
301 | ||
302 | Or even this: | |
303 | ||
304 | [source,c] | |
305 | ---- | |
306 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); | |
307 | ---- | |
308 | ||
309 | ||
4a41523d PP |
310 | [[how-to]] |
311 | === Instrument a module | |
beb0fb75 | 312 | |
4a41523d | 313 | Follow those steps to make your module loggable: |
beb0fb75 | 314 | |
4a41523d PP |
315 | . In your module's root directory, create a `logging.c` file with |
316 | this content: | |
317 | + | |
318 | -- | |
319 | [source,c] | |
320 | ---- | |
321 | /* | |
322 | * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/> | |
323 | * | |
324 | * Permission is hereby granted, free of charge, to any person obtaining a copy | |
325 | * of this software and associated documentation files (the "Software"), to deal | |
326 | * in the Software without restriction, including without limitation the rights | |
327 | * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
328 | * copies of the Software, and to permit persons to whom the Software is | |
329 | * furnished to do so, subject to the following conditions: | |
330 | * | |
331 | * The above copyright notice and this permission notice shall be included in | |
332 | * all copies or substantial portions of the Software. | |
333 | * | |
334 | * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
335 | * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
336 | * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
337 | * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
338 | * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
339 | * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
340 | * SOFTWARE. | |
341 | */ | |
342 | ||
343 | #define BT_LOG_OUTPUT_LEVEL my_module_log_level | |
344 | #include <babeltrace/logging-internal.h> | |
beb0fb75 | 345 | |
4a41523d PP |
346 | BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL"); |
347 | ---- | |
348 | -- | |
349 | + | |
350 | Replace `my_module_log_level` with the name of the symbol which holds | |
351 | the log level for your module (should be unique amongst all the log level | |
352 | symbols of the project). Replace `BABELTRACE_MY_MODULE_LOG_LEVEL` with | |
353 | the name of the environment variable from which to initialize your | |
354 | module's log level at construction time. `BT_LOG_INIT_LOG_LEVEL()` | |
355 | defines both the hidden log level symbol and a constructor which reads | |
356 | the environment variable and sets the log level symbol accordingly. | |
357 | ||
358 | . In your module's root directory, create a `logging.h` file with | |
359 | this content: | |
360 | + | |
361 | -- | |
beb0fb75 PP |
362 | [source,c] |
363 | ---- | |
4a41523d PP |
364 | #ifndef MY_MODULE_LOGGING_H |
365 | #define MY_MODULE_LOGGING_H | |
366 | ||
367 | /* | |
368 | * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/> | |
369 | * | |
370 | * Permission is hereby granted, free of charge, to any person obtaining a copy | |
371 | * of this software and associated documentation files (the "Software"), to deal | |
372 | * in the Software without restriction, including without limitation the rights | |
373 | * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
374 | * copies of the Software, and to permit persons to whom the Software is | |
375 | * furnished to do so, subject to the following conditions: | |
376 | * | |
377 | * The above copyright notice and this permission notice shall be included in | |
378 | * all copies or substantial portions of the Software. | |
379 | * | |
380 | * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
381 | * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
382 | * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
383 | * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
384 | * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
385 | * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
386 | * SOFTWARE. | |
387 | */ | |
388 | ||
389 | #define BT_LOG_OUTPUT_LEVEL my_module_log_level | |
beb0fb75 | 390 | #include <babeltrace/logging-internal.h> |
4a41523d PP |
391 | |
392 | BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level); | |
393 | ||
394 | #endif /* MY_MODULE_LOGGING_H */ | |
beb0fb75 | 395 | ---- |
4a41523d PP |
396 | -- |
397 | + | |
398 | Again, replace `my_module_log_level` with the name of your module's | |
399 | log level symbol. | |
400 | ||
401 | . Include the `logging.c` and `logging.h` in the `_SOURCES` variable | |
402 | of your module's object in your module's root `Makefile.am`. | |
beb0fb75 | 403 | |
4a41523d PP |
404 | To instrument a C source file (`.c`): |
405 | ||
406 | . At the top of the file, before the first `#include` line (if any), | |
407 | define your file's tag name and include the local `logging.h`: | |
408 | + | |
409 | -- | |
410 | [source,c] | |
411 | ---- | |
412 | #define BT_LOG_TAG "MY-MODULE-MY-FILE" | |
413 | #include "logging.h" | |
414 | ---- | |
415 | -- | |
416 | + | |
417 | A logging tag name is a namespace for a specific source file. Its name | |
418 | is part of every log message generated by the statements of the file. A | |
419 | logging tag name _must_ be only uppercase letters, digits, and the | |
99b6e073 | 420 | hyphen (`-`) character. See <<tags,Choose a tag>> for |
4a41523d PP |
421 | a list of standard tags. |
422 | ||
423 | . Use the <<logging-statements,logging statement macros>> in the file's | |
424 | functions to instrument it. | |
425 | ||
426 | To instrument a C header file (`.h`), if you have `static inline` | |
427 | functions in it: | |
428 | ||
429 | . Do not include any logging header. | |
430 | . Use the <<logging-statements,logging statement macros>> in the file's | |
431 | functions to instrument it, making each of them conditional to the | |
432 | existence of the macro you're using: | |
433 | + | |
434 | -- | |
435 | [source,c] | |
436 | ---- | |
437 | static inline | |
438 | void some_function(void) | |
439 | { | |
440 | /* ... */ | |
441 | ||
442 | #ifdef BT_LOGV | |
443 | BT_LOGV(...); | |
444 | #endif | |
445 | ||
446 | /* ... */ | |
447 | ||
448 | #ifdef BT_LOGW_STR | |
449 | BT_LOGW_STR(...); | |
450 | #endif | |
451 | ||
452 | /* ... */ | |
453 | } | |
454 | ---- | |
455 | -- | |
456 | + | |
457 | The C source files which include this header file determine if logging | |
458 | is enabled or not for them (if the source file is instrumented itself), | |
459 | and the tag of the included header's logging statement is the same as | |
460 | the C source file. | |
beb0fb75 PP |
461 | |
462 | ||
4a41523d | 463 | [[tags]] |
99b6e073 | 464 | === Choose a tag |
beb0fb75 | 465 | |
99b6e073 PP |
466 | For plugins, the format of the tag name for a given source file _must_ |
467 | be: | |
beb0fb75 | 468 | |
99b6e073 PP |
469 | [verse] |
470 | PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__] | |
beb0fb75 | 471 | |
99b6e073 PP |
472 | __PNAME__:: |
473 | Plugin's name. | |
beb0fb75 | 474 | |
99b6e073 PP |
475 | __CCNAME__:: |
476 | Component class's name. | |
beb0fb75 | 477 | |
99b6e073 PP |
478 | __CCTYPE__:: |
479 | Component class's type (`SRC`, `FLT`, or `SINK`). | |
beb0fb75 | 480 | |
99b6e073 PP |
481 | __FILE__:: |
482 | Additional information to specify the source file name or module. | |
beb0fb75 | 483 | |
99b6e073 | 484 | Examples: |
beb0fb75 | 485 | |
99b6e073 PP |
486 | * `PLUGIN-CTF-LTTNG-LIVE-SRC` |
487 | * `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER` | |
488 | * `PLUGIN-UTILS-MUXER-FLT` | |
beb0fb75 PP |
489 | |
490 | ||
491 | [[level]] | |
b4b9064d | 492 | == Choose a log level |
beb0fb75 PP |
493 | |
494 | Choosing the appropriate level for your logging statement is very | |
495 | important. | |
496 | ||
497 | [options="header,autowidth",cols="default,default,asciidoc,default"] | |
498 | |=== | |
499 | |Log level |Description |Use cases |Impact on performance | |
500 | ||
501 | |_FATAL_ | |
502 | |The program, library, or plugin cannot continue to work in this | |
503 | condition: it must be terminated immediately. | |
504 | ||
b4b9064d | 505 | A _FATAL_-level logging statement should always be followed by |
4a41523d | 506 | `abort()`. |
beb0fb75 PP |
507 | | |
508 | * Unexpected return values from system calls. | |
4a41523d PP |
509 | * Logic error in internal code, for example an unexpected value in a |
510 | `switch` statement. | |
beb0fb75 PP |
511 | |Almost none: should be executed in production. |
512 | ||
513 | |_ERROR_ | |
514 | |An important error which is somewhat not fatal, that is, the program, | |
515 | library, or plugin can continue to work after this, but you judge that | |
516 | it should be reported to the user. | |
517 | ||
518 | Usually, the program cannot recover from such an error, but it can at | |
519 | least exit cleanly. | |
520 | | | |
521 | * Memory allocation errors. | |
522 | * Failed to perform an operation which should work considering the | |
523 | implementation and the satisfied preconditions. For example, the | |
524 | failure to create an empty object (no parameters): most probably | |
525 | failed internally because of an allocation error. | |
99b6e073 | 526 | * Almost any error in terminal elements: CLI and plugins. |
beb0fb75 PP |
527 | |Almost none: should be executed in production. |
528 | ||
529 | |_WARN_ | |
530 | |A logic error which still allows the execution to continue. | |
6c1b33a8 PP |
531 | |
532 | _WARN_-level logging statements are for any error or weird action that | |
533 | is directly or indirectly caused by the user. For example, not having | |
4a41523d PP |
534 | enough memory is considered beyond the user's control, so we always |
535 | log memory errors with an _ERROR_ level (not _FATAL_ because we usually | |
536 | don't abort in this condition). | |
99b6e073 PP |
537 | |
538 | Almost all the library's errors are logged as warnings because they are | |
539 | caused by the user. | |
beb0fb75 | 540 | | |
6c1b33a8 PP |
541 | * Not honoring a public function's preconditions (NULL parameters, |
542 | index out of bounds, etc.). | |
543 | * Adding an invalid event class to a stream class which is already | |
544 | part of a trace. | |
beb0fb75 PP |
545 | + |
546 | For example, the caller tries to set a property of a frozen stream | |
547 | class. | |
548 | |Almost none: can be executed in production. | |
549 | ||
550 | |_INFO_ | |
551 | |Any useful information which a non-developer user would understand. | |
552 | | | |
553 | * Successful loading of a plugin (with name, version, etc.). | |
554 | * Successful connection to or disconnection from another system. | |
4a41523d | 555 | * An _optional_ subsystem cannot be loaded. |
beb0fb75 PP |
556 | |Very little: can be executed in production if |
557 | _INFO_ level information is desired. | |
558 | ||
559 | |_DEBUG_ | |
560 | |Something that only Babeltrace developers would be interested into. | |
561 | | | |
562 | * High-level function entry/exit. | |
563 | * Object creation, destruction, copying, and freezing. | |
564 | * The result of some computation/validation. | |
565 | |Noticeable, but not as much as the _VERBOSE_ level: not executed in | |
566 | production. | |
567 | ||
568 | |_VERBOSE_ | |
569 | |Low-level debugging context information. More appropriate for tracing | |
570 | in general. | |
571 | | | |
572 | * Reference count change. | |
573 | * Status of each iteration of a loop. | |
574 | * State machine's state change. | |
575 | * Data structure lookup/modification. | |
576 | * List of ELF sections found in a plugin. | |
577 | * Get or set an object's property. | |
578 | * Object comparison's intermediate results. | |
579 | |Huge: not executed in production. | |
580 | |=== | |
581 | ||
b4b9064d PP |
582 | Make sure not to use a _WARN_ (or higher) log level when the condition |
583 | leading to the logging statement can occur under normal circumstances. | |
584 | For example, a public function to get some object or property from an | |
585 | object by name or key that fails to find the value is not a warning: the | |
586 | user could legitimately use this function to check if the name/key | |
587 | exists in the object. In this case, use the _VERBOSE_ level (or do not | |
588 | log at all). If a numeric index is out of bounds, however, this | |
589 | qualifies for a _WARN_ level: such API functions have documented | |
590 | preconditions that the index must be in bounds (the user can always | |
591 | check with a count or size function). | |
592 | ||
beb0fb75 | 593 | |
b4b9064d PP |
594 | [[message]] |
595 | == Write an appropriate message | |
beb0fb75 PP |
596 | |
597 | Follow those rules when you write a logging statement's message: | |
598 | ||
599 | * Use an english sentence which starts with a capital letter. Start the | |
600 | sentence with the appropriate verb tense depending on the context. For | |
601 | example: | |
602 | + | |
603 | -- | |
b4b9064d PP |
604 | ** Beginning of operation (present continuous): _Creating ..._, |
605 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ | |
606 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, | |
607 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is | |
608 | also _set_) | |
beb0fb75 PP |
609 | -- |
610 | + | |
611 | For warning and error messages, you can start the message with _Cannot_ | |
b4b9064d | 612 | or _Failed to_ followed by a verb if it's appropriate. |
beb0fb75 PP |
613 | |
614 | * Do not include the log level in the message itself. For example, | |
615 | do not start the message with _Error while_ or _Warning:_. | |
616 | ||
617 | * Do not put newlines, tabs, or other special characters in the | |
618 | message, unless you want to log a string with such characters. Note | |
619 | that multiline log messages can be hard to parse, analyze, and filter, | |
b4b9064d PP |
620 | however, so prefer multiple `BT_LOG*()` statements over a single |
621 | statement with newlines. | |
beb0fb75 PP |
622 | |
623 | * **If there are fields that your logging statement must record**, | |
624 | follow the message with `:` followed by a space, then with the list of | |
625 | fields (more about this below). If there are no fields, end the | |
626 | sentence with a period. | |
627 | ||
628 | The statement's fields _must_ be a comma-separated list of | |
629 | +__name__=__value__+ tokens. Keep +__name__+ as simple as possible | |
b4b9064d PP |
630 | (lowercase if possible). If +__value__+ is a non-alphanumeric string, |
631 | put it between double quotes. Always use the `PRId64` and `PRIu64` | |
632 | specifiers when logging `int64_t` and `uint64_t` values. | |
beb0fb75 PP |
633 | |
634 | Example: | |
635 | ||
636 | "Cannot add event class to stream class: stream-class-addr=%p, " | |
b4b9064d | 637 | "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " |
beb0fb75 PP |
638 | "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64 |
639 | ||
640 | By following a standard format for the statement fields, it is easier | |
641 | to use tools like https://www.elastic.co/products/logstash[Logstash] | |
642 | to split fields and analyze logs. | |
643 | ||
644 | Prefer the following suffixes in field names: | |
645 | ||
646 | [options="header,autowidth"] | |
647 | |=== | |
648 | |Field name suffix |Description |Format specifier | |
649 | ||
650 | |`-addr` |Memory address |`%p` | |
651 | |`-fd` |File descriptor |`%d` | |
652 | |`-fp` |File stream (`FILE *`) |`%p` | |
653 | |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "` | |
654 | |`-name` |Object's name |`\"%s\"` | |
beb0fb75 PP |
655 | |=== |
656 | ||
657 | ||
658 | == Output | |
659 | ||
660 | The log is printed to the standard error stream. A log line contains the | |
4a41523d | 661 | time, the process and thread IDs, the <<level,log level>>, the tag name, |
b4b9064d PP |
662 | the source's function name, file name and line number, and the |
663 | <<message,message>>. | |
beb0fb75 PP |
664 | |
665 | Example: | |
666 | ||
667 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 | |
668 | ||
669 | You can easily filter the log with `grep` or `ag`. For example, to | |
670 | keep only the _WARN_-level log messages that the `VALUES` module | |
671 | generates: | |
672 | ||
673 | $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE | |
674 | $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES' |