Commit | Line | Data |
---|---|---|
beb0fb75 PP |
1 | = Babeltrace logging guide |
2 | Philippe Proulx | |
3 | 7 May 2017 | |
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 | |
33 | user can control is the current log level of the library with | |
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 | ||
70 | === Log levels === | |
71 | ||
72 | The API offers the following log levels: | |
73 | ||
74 | * _VERBOSE_ | |
75 | * _DEBUG_ | |
76 | * _INFO_ | |
77 | * _WARN_ | |
78 | * _ERROR_ | |
79 | * _FATAL_ | |
80 | ||
81 | See <<level,how to decide which one to use>> below. | |
82 | ||
83 | There are two important log level variables: | |
84 | ||
85 | [[build-time-log-level]]Build-time, minimal log level:: | |
86 | The minimal log level, or build-time log level, is set at build | |
87 | time and determines the minimal log level which can be executed. | |
88 | This applies to all the subprojects and modules (CLI, library, | |
89 | plugins, etc.). | |
90 | + | |
91 | All the logging statements with a level below this level are **not built | |
92 | at all**. All the logging statements with a level equal to or greater | |
93 | than this level _can_ be executed, depending on the run-time log level | |
94 | (see below). | |
95 | + | |
96 | You can set this level at configuration time with the | |
97 | `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example: | |
98 | + | |
99 | -- | |
100 | ---- | |
101 | $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure | |
102 | ---- | |
103 | -- | |
104 | + | |
105 | The default build-time log level is `DEBUG`. For optimal performance, | |
106 | set it to `NONE`, which effectively disables all logging in all the | |
107 | Babeltrace subprojects. | |
108 | + | |
109 | The library's public API provides `bt_logging_get_minimal_level()` to | |
110 | get the configured minimal log level. | |
111 | ||
112 | [[run-time-log-level]]Run-time, dynamic log level:: | |
113 | The dynamic log level is set at run-time and determines the current, | |
114 | active log level. All the logging statements with a level below this | |
115 | level are not executed, but they evaluate the condition. All the | |
116 | logging statements with a level equal to or greater than this level | |
117 | are executed, provided that their level is also enabled at build | |
118 | time (see above). | |
119 | + | |
120 | In `zf_log`, there is a concept of a global run-time log level which | |
121 | uses the `_bt_log_global_output_lvl` symbol. In practice, we never use | |
122 | this symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined | |
123 | to a module-wise or subproject-wise hidden symbol before including | |
124 | `<babeltrace/logging-internal.h>`. In the library, | |
125 | `<babeltrace/lib-logging-internal.h>` does this job: just include | |
126 | this header which defines `BT_LOG_OUTPUT_LEVEL` to the appropriate | |
127 | symbol before it includes `<babeltrace/logging-internal.h>`. In plugins, | |
128 | for example, there is one log level per component class, which makes | |
129 | log filtering easier during execution. | |
130 | + | |
131 | In libbabeltrace, the user can set the current run-time log level with | |
132 | the `bt_logging_set_global_level()` function, for example: | |
133 | + | |
134 | -- | |
135 | [source,c] | |
136 | ---- | |
137 | bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO); | |
138 | ---- | |
139 | -- | |
140 | + | |
141 | The library's initial run-time log level is defined by the | |
142 | `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable (`VERBOSE`, `DEBUG`, | |
143 | `INFO`, `WARN`, `ERROR`, `FATAL`, or `NONE`), or set to _NONE_ if this | |
144 | environment variable is undefined. | |
145 | + | |
146 | Other subprojects have their own way of setting their run-time log | |
147 | level. For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL` | |
148 | environment variable, and the `text.pretty` sink component class | |
149 | initializes its log level thanks to the | |
150 | `BABELTRACE_PLUGIN_TEXT_PRETTY_SINK_LOG_LEVEL` environment variable | |
151 | (also _NONE_ by default). | |
152 | + | |
153 | Make sure that there is a documented way to initialize or modify the | |
154 | log level of your subproject or module, and that it's set to _NONE_ | |
155 | by default. | |
156 | ||
157 | ||
158 | === Logging statement macros | |
159 | ||
160 | The Babeltrace logging statement macros work just like `printf()` and | |
161 | contain their log level in their name: | |
162 | ||
163 | `BT_LOGV("format string", ...)`:: | |
164 | Standard verbose logging statement. | |
165 | ||
166 | `BT_LOGD("format string", ...)`:: | |
167 | Standard debug logging statement. | |
168 | ||
169 | `BT_LOGI("format string", ...)`:: | |
170 | Standard info logging statement. | |
171 | ||
172 | `BT_LOGW("format string", ...)`:: | |
173 | Standard warning logging statement. | |
174 | ||
175 | `BT_LOGE("format string", ...)`:: | |
176 | Standard error logging statement. | |
177 | ||
178 | `BT_LOGF("format string", ...)`:: | |
179 | Standard fatal logging statement. | |
180 | ||
181 | `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`:: | |
182 | Memory verbose logging statement. | |
183 | ||
184 | `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`:: | |
185 | Memory debug logging statement. | |
186 | ||
187 | `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`:: | |
188 | Memory info logging statement. | |
189 | ||
190 | `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`:: | |
191 | Memory warning logging statement. | |
192 | ||
193 | `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`:: | |
194 | Memory error logging statement. | |
195 | ||
196 | `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`:: | |
197 | Memory fatal logging statement. | |
198 | ||
199 | `BT_LOGV_STR("preformatted string")`:: | |
200 | Preformatted string verbose logging statement. | |
201 | ||
202 | `BT_LOGD_STR("preformatted string")`:: | |
203 | Preformatted string debug logging statement. | |
204 | ||
205 | `BT_LOGI_STR("preformatted string")`:: | |
206 | Preformatted string info logging statement. | |
207 | ||
208 | `BT_LOGW_STR("preformatted string")`:: | |
209 | Preformatted string warning logging statement. | |
210 | ||
211 | `BT_LOGE_STR("preformatted string")`:: | |
212 | Preformatted string error logging statement. | |
213 | ||
214 | `BT_LOGF_STR("preformatted string")`:: | |
215 | Preformatted string fatal logging statement. | |
216 | ||
217 | ||
218 | === Conditional logging | |
219 | ||
220 | `BT_LOG_IF(cond, statement)`:: | |
221 | Execute `statement` only if `cond` is true. | |
222 | + | |
223 | Example: | |
224 | + | |
225 | -- | |
226 | [source,c] | |
227 | ---- | |
228 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); | |
229 | ---- | |
230 | -- | |
231 | ||
232 | To check the <<build-time-log-level,build-time log level>>: | |
233 | ||
234 | [source,c] | |
235 | ---- | |
236 | #if BT_LOG_ENABLED_DEBUG | |
237 | ... | |
238 | #endif | |
239 | ---- | |
240 | ||
241 | This tests if the _DEBUG_ level was enabled at build-time. This | |
242 | means that the current, dynamic log level _could_ be _DEBUG_, but it | |
243 | could also be higher. The rule of thumb is to use only logging | |
244 | statements at the same level in a `BT_LOG_ENABLED_*` conditional block. | |
245 | ||
246 | The available definitions for build-time conditions are: | |
247 | ||
248 | * `BT_LOG_ENABLED_VERBOSE` | |
249 | * `BT_LOG_ENABLED_DEBUG` | |
250 | * `BT_LOG_ENABLED_INFO` | |
251 | * `BT_LOG_ENABLED_WARN` | |
252 | * `BT_LOG_ENABLED_ERROR` | |
253 | * `BT_LOG_ENABLED_FATAL` | |
254 | ||
255 | To check the current, <<run-time-log-level,run-time log level>>: | |
256 | ||
257 | [source,c] | |
258 | ---- | |
259 | if (BT_LOG_ON_DEBUG) { | |
260 | ... | |
261 | } | |
262 | ---- | |
263 | ||
264 | This tests if the _DEBUG_ log level is dynamically turned on | |
265 | (implies that it's also enabled at build-time). This check could have a | |
266 | noticeable impact on performance. | |
267 | ||
268 | The available definitions for run-time conditions are: | |
269 | ||
270 | * `BT_LOG_ON_VERBOSE` | |
271 | * `BT_LOG_ON_DEBUG` | |
272 | * `BT_LOG_ON_INFO` | |
273 | * `BT_LOG_ON_WARN` | |
274 | * `BT_LOG_ON_ERROR` | |
275 | * `BT_LOG_ON_FATAL` | |
276 | ||
277 | Those macros check the subproject-specific or module-specific log level | |
278 | symbol (defined by `BT_LOG_OUTPUT_LEVEL`). | |
279 | ||
280 | Never, ever write code which would be executed only to compute the | |
281 | fields of a logging statement outside a conditional logging scope, | |
282 | for example: | |
283 | ||
284 | [source,c] | |
285 | ---- | |
286 | int number = get_number_of_event_classes_with_property_x(...); | |
287 | BT_LOGD("Bla bla: number=%d", number); | |
288 | ---- | |
289 | ||
290 | Do this instead: | |
291 | ||
292 | [source,c] | |
293 | ---- | |
294 | if (BT_LOG_ON_DEBUG) { | |
295 | int number = get_number_of_event_classes_with_property_x(...); | |
296 | BT_LOGD("Bla bla: number=%d", number); | |
297 | } | |
298 | ---- | |
299 | ||
300 | Or even this: | |
301 | ||
302 | [source,c] | |
303 | ---- | |
304 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); | |
305 | ---- | |
306 | ||
307 | ||
308 | [[tag]] | |
309 | == Tag | |
310 | ||
311 | Before including `<babeltrace/logging-internal.h>` (or | |
312 | `<babeltrace/lib-logging-internal.h>`) in your C source file, define | |
313 | `BT_LOG_TAG` to a name which represents your module. The tag name _must_ | |
314 | be only uppercase letters/digits and the hyphen (`-`) character. | |
315 | ||
316 | For example: | |
317 | ||
318 | [source,c] | |
319 | ---- | |
320 | #define BT_LOG_TAG "EVENT-CLASS" | |
321 | #include <babeltrace/logging-internal.h> | |
322 | ---- | |
323 | ||
324 | A tag is conceptually similar to a logger name. | |
325 | ||
326 | ||
327 | === Babeltrace tags | |
328 | ||
329 | ==== CTF IR (library) | |
330 | ||
331 | [options="header,autowidth"] | |
332 | |=== | |
333 | |Subsystem/object |Tag name | |
334 | ||
335 | |Attributes |`ATTRS` | |
336 | |Clock class and values |`CLOCK-CLASS` | |
337 | |Event class |`EVENT-CLASS` | |
338 | |Event |`EVENT` | |
339 | |Field path |`FIELD-PATH` | |
340 | |Field types |`FIELD-TYPES` | |
341 | |Fields |`FIELDS` | |
342 | |Packet |`PACKET` | |
343 | |Resolver |`RESOLVE` | |
344 | |Stream class |`STREAM-CLASS` | |
345 | |Stream |`STREAM` | |
346 | |Trace |`TRACE` | |
347 | |Validation |`VALIDATION` | |
348 | |Visitor |`VISITOR` | |
349 | |=== | |
350 | ||
351 | ||
352 | ==== CTF writer (library) | |
353 | ||
354 | [options="header,autowidth"] | |
355 | |=== | |
356 | |Subsystem/object |Tag name | |
357 | ||
358 | |Clock |`CTF-WRITER-CLOCK` | |
359 | |CTF writer |`CTF-WRITER` | |
360 | |Serialization |`CTF-WRITER-SER` | |
361 | |=== | |
362 | ||
363 | ||
364 | ==== Graph (library) | |
365 | ||
366 | [options="header,autowidth"] | |
367 | |=== | |
368 | |Subsystem/object |Tag name | |
369 | ||
370 | |Clock class priority map |`CC-PRIO-MAP` | |
371 | |Component (common) |`COMP` | |
372 | |Component class |`COMP-CLASS` | |
373 | |Connection |`CONNECTION` | |
374 | |Filter component |`COMP-FILTER` | |
375 | |Graph |`GRAPH` | |
376 | |Notification iterator |`NOTIF-ITER` | |
377 | |Port |`PORT` | |
378 | |Sink component |`COMP-SINK` | |
379 | |Source component |`COMP-SOURCE` | |
380 | |=== | |
381 | ||
382 | ==== Notifications (library) | |
383 | ||
384 | [options="header,autowidth"] | |
385 | |=== | |
386 | |Subsystem/object |Tag name | |
387 | ||
388 | |Event notification |`NOTIF-EVENT` | |
389 | |Inacitivity notification |`NOTIF-INACTIVITY` | |
390 | |Notification |`NOTIF` | |
391 | |Packet notification |`NOTIF-PACKET` | |
392 | |Stream notification |`NOTIF-STREAM` | |
393 | |=== | |
394 | ||
395 | ||
396 | ==== Plugin (library) | |
397 | ||
398 | [options="header,autowidth"] | |
399 | |=== | |
400 | |Subsystem/object |Tag name | |
401 | ||
402 | |Plugin |`PLUGIN` | |
403 | |Python plugin provider |`PLUGIN-PY` | |
404 | |Shared object plugin provider |`PLUGIN-SO` | |
405 | |=== | |
406 | ||
407 | ||
408 | ==== Values (library) | |
409 | ||
410 | [options="header,autowidth"] | |
411 | |=== | |
412 | |Subsystem/object |Tag name | |
413 | ||
414 | |Values |`VALUES` | |
415 | |=== | |
416 | ||
417 | ||
418 | ==== Reference counting (library) | |
419 | ||
420 | [options="header,autowidth"] | |
421 | |=== | |
422 | |Subsystem/object |Tag name | |
423 | ||
424 | |Reference counting |`REF` | |
425 | |=== | |
426 | ||
427 | ||
428 | ==== Common (library) | |
429 | ||
430 | [options="header,autowidth"] | |
431 | |=== | |
432 | |Subsystem/object |Tag name | |
433 | ||
434 | |Common |`COMMON` | |
435 | |=== | |
436 | ||
437 | ||
438 | ==== CLI | |
439 | ||
440 | [options="header,autowidth"] | |
441 | |=== | |
442 | |Subsystem/object |Tag name | |
443 | ||
444 | |CLI (main) |`CLI` | |
445 | |CLI configuration (common) |`CLI-CFG` | |
446 | |CLI configuration from CLI arguments |`CLI-CFG-ARGS` | |
447 | |CLI connection configuration from CLI arguments |`CLI-CFG-ARGS-CONNECT` | |
448 | |=== | |
449 | ||
450 | ||
451 | ==== libctfcopytrace (plugin convenience library) | |
452 | ||
453 | [options="header,autowidth"] | |
454 | |=== | |
455 | |Subsystem/object |Tag name | |
456 | ||
457 | |Clock fields |`LIBCTFCOPYTRACE-CLOCK-FIELDS` | |
458 | |libctfcopytrace |`LIBCTFCOPYTRACE` | |
459 | |=== | |
460 | ||
461 | ||
462 | ==== `ctf` plugin | |
463 | ||
464 | [options="header,autowidth"] | |
465 | |=== | |
466 | |Subsystem/object |Tag name | |
467 | ||
468 | |Plugin (main) |`PLUGIN-CTF` | |
469 | |Common: BTR |`PLUGIN-CTF-BTR` | |
470 | |Common: CTF IR generation metadata visitor |`PLUGIN-CTF-METADATA-IR-VISITOR` | |
471 | |Common: Metadata decoder |`PLUGIN-CTF-METADATA-DECODER` | |
472 | |Common: Metadata lexer |`PLUGIN-CTF-METADATA-LEXER` | |
473 | |Common: Metadata parser |`PLUGIN-CTF-METADATA-PARSER` | |
474 | |Common: Notification iterator |`PLUGIN-CTF-NOTIF-ITER` | |
475 | |`fs` sink (main) |`PLUGIN-CTF-FS-SINK` | |
476 | |`fs` sink: write |`PLUGIN-CTF-FS-SINK-WRITE` | |
477 | |`fs` source (main) |`PLUGIN-CTF-FS-SRC` | |
478 | |`fs` source: data stream |`PLUGIN-CTF-FS-SRC-DS` | |
479 | |`fs` source: file |`PLUGIN-CTF-FS-SRC-FILE` | |
480 | |`fs` source: metadata |`PLUGIN-CTF-FS-SRC-METADATA` | |
481 | |`lttng-live` source (main) |`PLUGIN-CTF-LTTNG-LIVE` | |
482 | |`lttng-live` source: data stream |`PLUGIN-CTF-LTTNG-LIVE-DS` | |
483 | |`lttng-live` source: metadata |`PLUGIN-CTF-LTTNG-LIVE-METADATA` | |
484 | |`lttng-live` source: viewer connection |`PLUGIN-CTF-LTTNG-LIVE-VIEWER` | |
485 | |=== | |
486 | ||
487 | ||
488 | ==== `lttng-utils` plugin | |
489 | ||
490 | [options="header,autowidth"] | |
491 | |=== | |
492 | |Subsystem/object |Tag name | |
493 | ||
494 | |Plugin (main) |`PLUGIN-LTTNG-UTILS` | |
495 | |`debug-info` filter (main) |`PLUGIN-LTTNG-UTILS-DBG-INFO` | |
496 | |`debug-info` filter: binary info |`PLUGIN-LTTNG-UTILS-DBG-INFO-BIN-INFO` | |
497 | |`debug-info` filter: copy |`PLUGIN-LTTNG-UTILS-DBG-INFO-COPY` | |
498 | |`debug-info` filter: CRC32 |`PLUGIN-LTTNG-UTILS-DBG-INFO-CRC32` | |
499 | |`debug-info` filter: DWARF |`PLUGIN-LTTNG-UTILS-DBG-INFO-DWARF` | |
500 | |=== | |
501 | ||
502 | ||
503 | ==== `text` plugin | |
504 | ||
505 | [options="header,autowidth"] | |
506 | |=== | |
507 | |Subsystem/object |Tag name | |
508 | ||
509 | |Plugin (main) |`PLUGIN-TEXT` | |
510 | |`pretty` filter (main) |`PLUGIN-TEXT-PRETTY` | |
511 | |`pretty` filter: print |`PLUGIN-TEXT-PRETTY-PRINT` | |
512 | |=== | |
513 | ||
514 | ||
515 | ==== `utils` plugin | |
516 | ||
517 | [options="header,autowidth"] | |
518 | |=== | |
519 | |Subsystem/object |Tag name | |
520 | ||
521 | |Plugin (main) |`PLUGIN-UTILS` | |
522 | |`dummy` sink (main) |`PLUGIN-UTILS-DUMMY` | |
523 | |`muxer` filter (main) |`PLUGIN-UTILS-MUXER` | |
524 | |`trimmer` filter (main) |`PLUGIN-UTILS-TRIMMER` | |
525 | |`trimmer` filter: copy |`PLUGIN-UTILS-TRIMMER-COPY` | |
526 | |`trimmer` filter: iterator |`PLUGIN-UTILS-TRIMMER-ITER` | |
527 | |=== | |
528 | ||
529 | ||
530 | [[level]] | |
531 | == Log level | |
532 | ||
533 | Choosing the appropriate level for your logging statement is very | |
534 | important. | |
535 | ||
536 | [options="header,autowidth",cols="default,default,asciidoc,default"] | |
537 | |=== | |
538 | |Log level |Description |Use cases |Impact on performance | |
539 | ||
540 | |_FATAL_ | |
541 | |The program, library, or plugin cannot continue to work in this | |
542 | condition: it must be terminated immediately. | |
543 | ||
544 | An assertion is usually an indicator of where you should put a | |
545 | _FATAL_-level logging statement. In Babeltrace, however, memory | |
546 | allocation errors are usually propagated back to the caller, so they | |
547 | belong to the _ERROR_ log level. | |
548 | | | |
549 | * Unexpected return values from system calls. | |
550 | |Almost none: should be executed in production. | |
551 | ||
552 | |_ERROR_ | |
553 | |An important error which is somewhat not fatal, that is, the program, | |
554 | library, or plugin can continue to work after this, but you judge that | |
555 | it should be reported to the user. | |
556 | ||
557 | Usually, the program cannot recover from such an error, but it can at | |
558 | least exit cleanly. | |
559 | | | |
560 | * Memory allocation errors. | |
561 | * Failed to perform an operation which should work considering the | |
562 | implementation and the satisfied preconditions. For example, the | |
563 | failure to create an empty object (no parameters): most probably | |
564 | failed internally because of an allocation error. | |
565 | |Almost none: should be executed in production. | |
566 | ||
567 | |_WARN_ | |
568 | |A logic error which still allows the execution to continue. | |
569 | | | |
570 | * Unexpected values for function parameters. | |
571 | * Other user-induced errors (the user does not honor a function's | |
572 | preconditions). | |
573 | + | |
574 | For example, the caller tries to set a property of a frozen stream | |
575 | class. | |
576 | |Almost none: can be executed in production. | |
577 | ||
578 | |_INFO_ | |
579 | |Any useful information which a non-developer user would understand. | |
580 | | | |
581 | * Successful loading of a plugin (with name, version, etc.). | |
582 | * Successful connection to or disconnection from another system. | |
583 | * An optional subsystem cannot be loaded. | |
584 | |Very little: can be executed in production if | |
585 | _INFO_ level information is desired. | |
586 | ||
587 | |_DEBUG_ | |
588 | |Something that only Babeltrace developers would be interested into. | |
589 | | | |
590 | * High-level function entry/exit. | |
591 | * Object creation, destruction, copying, and freezing. | |
592 | * The result of some computation/validation. | |
593 | |Noticeable, but not as much as the _VERBOSE_ level: not executed in | |
594 | production. | |
595 | ||
596 | |_VERBOSE_ | |
597 | |Low-level debugging context information. More appropriate for tracing | |
598 | in general. | |
599 | | | |
600 | * Reference count change. | |
601 | * Status of each iteration of a loop. | |
602 | * State machine's state change. | |
603 | * Data structure lookup/modification. | |
604 | * List of ELF sections found in a plugin. | |
605 | * Get or set an object's property. | |
606 | * Object comparison's intermediate results. | |
607 | |Huge: not executed in production. | |
608 | |=== | |
609 | ||
610 | ||
611 | == Message | |
612 | ||
613 | Follow those rules when you write a logging statement's message: | |
614 | ||
615 | * Use an english sentence which starts with a capital letter. Start the | |
616 | sentence with the appropriate verb tense depending on the context. For | |
617 | example: | |
618 | + | |
619 | -- | |
620 | ** _Creating ..._ | |
621 | ** _Created ..._ or _Successfully created ..._ | |
622 | -- | |
623 | + | |
624 | For warning and error messages, you can start the message with _Cannot_ | |
625 | followed by a verb if it's appropriate. | |
626 | ||
627 | * Do not include the log level in the message itself. For example, | |
628 | do not start the message with _Error while_ or _Warning:_. | |
629 | ||
630 | * Do not put newlines, tabs, or other special characters in the | |
631 | message, unless you want to log a string with such characters. Note | |
632 | that multiline log messages can be hard to parse, analyze, and filter, | |
633 | however. | |
634 | ||
635 | * **If there are fields that your logging statement must record**, | |
636 | follow the message with `:` followed by a space, then with the list of | |
637 | fields (more about this below). If there are no fields, end the | |
638 | sentence with a period. | |
639 | ||
640 | The statement's fields _must_ be a comma-separated list of | |
641 | +__name__=__value__+ tokens. Keep +__name__+ as simple as possible | |
642 | (lowercase if possible). If +__value__+ is a string, put it between | |
643 | double quotes. | |
644 | ||
645 | Example: | |
646 | ||
647 | "Cannot add event class to stream class: stream-class-addr=%p, " | |
648 | "stream-class-name=\"%s\", stream-class-id=%" PRId64 | |
649 | "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64 | |
650 | ||
651 | By following a standard format for the statement fields, it is easier | |
652 | to use tools like https://www.elastic.co/products/logstash[Logstash] | |
653 | to split fields and analyze logs. | |
654 | ||
655 | Prefer the following suffixes in field names: | |
656 | ||
657 | [options="header,autowidth"] | |
658 | |=== | |
659 | |Field name suffix |Description |Format specifier | |
660 | ||
661 | |`-addr` |Memory address |`%p` | |
662 | |`-fd` |File descriptor |`%d` | |
663 | |`-fp` |File stream (`FILE *`) |`%p` | |
664 | |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "` | |
665 | |`-name` |Object's name |`\"%s\"` | |
666 | |`-ref-cnt` |Object's reference count |`%u` | |
667 | |=== | |
668 | ||
669 | ||
670 | == Output | |
671 | ||
672 | The log is printed to the standard error stream. A log line contains the | |
673 | time, the process and thread IDs, the log level, the tag, the source's | |
674 | function name, file name and line number, and the message. | |
675 | ||
676 | Example: | |
677 | ||
678 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 | |
679 | ||
680 | You can easily filter the log with `grep` or `ag`. For example, to | |
681 | keep only the _WARN_-level log messages that the `VALUES` module | |
682 | generates: | |
683 | ||
684 | $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE | |
685 | $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES' |