1# Structured Logging
2
3There are currently two APIs for structured logging:
4[log](../lib/include/phosphor-logging/log.hpp) and
5[lg2](../lib/include/phosphor-logging/lg2.hpp). If your code is C++20 (or later)
6it is preferred to use `lg2`.
7
8## Why structured logging?
9
10Structured logging is a method of logging where every variable piece of data is
11tagged with some identifier for the data. This is opposite of unstructured
12logging where logged events are free-form strings.
13
14The principal logging daemon in OpenBMC (systemd-journald) natively supports
15structured logging. As a result, there are some designs in place where specific
16structured events are added to the journal and downstream these events can be
17consumed. For example, one implementation of the IPMI SEL utilizes specific
18journal structured data to stored and later retrieve SEL events.
19
20Even if an argument might be made against the merits of using the journal as a
21form of IPC, the value of structured logging persists. It is very common as part
22of various failure-analysis operations, either on the part of a system
23manufacturer or an end-user, to need to interrogate the system logs to determine
24when/where/why a situation degraded. With unstructured logging, the
25implementation is left chasing message format and data changes, where as with
26structured logging the format is somewhat static and easily parsed.
27
28A specific example of where structured logging is beneficial is a service which
29gathers `error` or higher log reports and creates issues when a new or unknown
30signature is discovered. If the only information available is an unstructured
31string, any kind of signature identification requires creating a regular
32expression (likely). With structured log, specific identifiers can be used as
33the error signature while others are ignored. For instance, maybe a specific
34`ERROR_RC` is critical to identifying the scenario but `FILE_PATH` is variable
35and ignored.
36
37For deeper understanding of the OpenBMC logging subsystem, it may be useful to
38read the manpages for `man 1 journalctl` and `man 3 sd_journal_send`. Generally
39accepted log-levels and their definition is historically documented in
40`man 3 syslog`.
41
42## log
43
44The pre-C++20 logging APIs presented by phosphor-logging are
45`phosphor::logging::log`. The basic format of a log call is:
46
47```cpp
48    log<level>("A message", entry("TAG0=%s", "value"), entry("TAG1=%x", 2));
49```
50
51Each log call has a level or priority, which corresponds to syslog priorities,
52such as 'debug', 'info', 'emergency', a free-form message string, and any number
53of entries, which are key-value pairs of data.
54
55The 'key' of an entry is an upper-case tag for the data along with a
56printf-style format string for the data. Journald imposes some restrictions on
57the tag: it must be all capital letters, numbers, or underscores and must not
58start with an underscore. Unfortunately, if these restrictions are not followed
59or the printf string is invalid for the data, the code will compile but journald
60may silently drop the log request (or pieces of it).
61
62It is highly discouraged to dynamically create the free-form message string
63because the contents are then, effectively, unstructured.
64
65## lg2
66
67The post-C++20 logging APIs presented by phosphor-logging are `lg2::log`. The
68basic format of a log call is:
69
70```cpp
71    lg2::level("A {TAG0} occured.", "TAG0", "foo"s, "TAG1", lg2::hex, 2);
72```
73
74Each log call has a level or priority, but the level is indicated by the
75function call name (such as `lg2::debug(...)`). The log call also has a
76free-form message string and any number of entries indicated by 2 or 3 argument
77sets:
78
79- key name (with the same `[_A-Z0-9]` requirements imposed by journald).
80- [optional] set of format flags
81- data value
82
83The free-form message may also optionally contain brace-wrapped key names, for
84which the message will be dynamically modified to contain the formatted value in
85place of the `{KEY}`. This enables human-friendly message strings to be formed
86without relying on verbose journald output modes.
87
88Note: Since a free-form message with data can be created using the `{KEY}`
89mechanism, no other string formatting libraries are necessary or should be used.
90Avoiding the `{KEY}` feature causes the journal messages to become unstructured.
91Do not use `sstream` or `{fmt}` to format the message!
92
93The supported format flags are:
94
95- `bin`, `dec`, `hex`
96  - The [integer] data should be formatted in the requested manner.
97  - Decimal is the default.
98  - Examples:
99    - `bin, 0xabcd` -> `0b1010101111001101`
100    - `hex, 1234` -> `0x4d2`
101- `field8`, `field16`, `field32`, `field64`
102  - The [integer] data should be padded as if it were a field of specified
103    bit-length (useful only for `bin` or `hex` data).
104  - Examples:
105    - `(bin | field8), 0xff` -> `0b11111111`
106    - `(hex | field16), 10` -> `0x000a`
107
108Format flags can be OR'd together as necessary: `hex | field32`.
109
110The APIs can handle (and format appropriately) any data of the following types:
111signed or unsigned integers, floating point numbers, booleans, strings
112(C-strings, std::strings, or std::string_views), sdbusplus enums, exceptions,
113and pointers.
114
115The APIs also perform compile-time analysis of the arguments to give descriptive
116error messages for incorrect parameters or format flags. Some examples are:
117
118- `(dec | hex)` yields:
119  - `error: static assertion failed: Conflicting flags found for value type.`
120- `dec` applied to a string yields:
121  - `error: static assertion failed: Prohibited flag found for value type.`
122- Missing a key yields:
123  - `error: static assertion failed: Found value without expected header field.`
124- Missing data yields:
125  - `error: static assertion failed: Found header field without expected data.`
126- Missing a message yields:
127  - `error: use of deleted function ‘lg2::debug<>::debug()’`
128
129### LOG2_FMTMSG key
130
131The API adds an extra journald key to represent the original message prior to
132`{KEY}` replacement, which is saved with the `LOG2_FMTMSG` key. This is done to
133facilitate searching the journal with a known fixed version of the message
134(prior to the dynamic replacement).
135
136### Key format checking
137
138The journald APIs require that keys (also called data 'headers') may only
139contain underscore, uppercase letters, or numbers (`[_A-Z0-9]`) and may not
140start with underscores. If these requirements are ignored, the journal API
141silently drops journal requests. In order to prevent silent bugs, the code
142performs compile-time checking of these requirements.
143
144The code that enables compile-time header checking imposes two constraints:
145
1461. Keys / headers must be passed as constant C-string values.
147   - `"KEY"` is valid; `"KEY"s` or `variable_key` is not.
1482. Any constant C-string may be interpreted as a key and give non-obvious
149   compile warnings about format violations.
150   - Constant C-strings (`"a string"`) should be passed as a C++ literal
151     (`"a string"s`) instead.
152
153### stderr output
154
155When running an application or daemon on a console or SSH session, it might not
156be obvious that the application is writing to the journal. The `lg2` APIs detect
157if the application is running on a TTY and additionally log to the TTY.
158
159Output to stderr can also be forced by setting the `LG2_FORCE_STDERR`
160environment variable to any value. This is especially useful to see log output
161in OpenBMC CI test verfication.
162
163The format of information sent to the TTY can be adjusted by setting the desired
164format string in the `LG2_FORMAT` environment variable. Supported fields are:
165
166- `%%` : a `'%'` literal
167- `%f` : the logging function's name
168- `%F` : the logging function's file
169- `%l` : the log level as an integer
170- `%L` : the logging function's line number
171- `%m` : the lg2 message
172
173The default format is `"<%l> %m"`.
174
175### Why a new API?
176
177There were a number of issues raised by `logging::log` which are not easily
178fixed with the existing API.
179
1801. The mixture of template and temporary-constructed `entry` parameters is
181   verbose and clumsy. `lg2` is far more succinct in this regard.
1822. The printf format-strings were error prone and potentially missed in code
183   reviews. `lg2` eliminates the need for printf strings by generating the
184   formatting internally.
1853. `logging::log` generates incorrect code location information (see
186   openbmc/openbmc#2297). `lg2` uses C++20's `source_location` to, by default,
187   generate correct code location info and can optionally be passed a
188   non-defaulted `source_location` for rare but appropriate cases.
1894. The previous APIs had no mechanism to generate dynamic user-friendly strings
190   which caused some developers to rely on external formatting libraries such as
191   `{fmt}`. `{KEY}` replacement is now a core feature of the new API.
1925. When running on a TTY, `logging::log` sent data to journal and the TTY was
193   silent. This resulted in some applications creating custom code to write some
194   data to `stdout` and some to `logging::log` APIs. `lg2` automatically detects
195   if it is running on a TTY and duplicates logging data to the console and the
196   journal.
197
198It is possible #3 and #5 could be fixed with the existing APIs, but the
199remainder are only possible to be resolved with changes to the API syntax.
200
201### Why C++20?
202
203Solving issue openbmc/openbmc#2297 requires C++20's `source_location` feature.
204It is possible that this could be solved in the `logging::log` APIs by utilizing
205`#ifdef` detection of the `source_location` feature so that C++20 applications
206gain this support.
207
208Implementing much of the syntactic improvements of the `lg2` API is made
209possible by leveraging C++20's Concepts feature. Experts in C++ may argue that
210this could be implemented in earlier revisions of C++ using complex SFINAE
211techniques with templated-class partial-specialization and overloading. Those
212experts are more than welcome to implement the `lg2` API in C++17 on their own.
213
214### Why didn't you do ...?
215
216> Why didn't you just use `{fmt}`?
217
218`{fmt}` is a great API for creating unstructured logging strings, but we are
219trying to create structured logging. `{fmt}` doesn't address that problem
220domain.
221
222> Why invent your own formatting and not use `{fmt}`?
223
224The formatting performed by this API is purposefully minimal. `{fmt}` is very
225capable and especially apt for human-facing string formatting. That is not the
226typical use-case for our logging. Instead we prioritized the following:
227
2281. Reasonable syntactic ergonomics so that the API can easily be adopted.
2292. Simple, consistent, machine parse-able data contents.
2303. Sufficient human-facing messages for developer-level debug.
2314. Very tight code generation at logging call sites and reasonably performant
232   code.
233
234(1) The lg2 API is roughly equivalent to `printf`, `{fmt}`, `cout` in terms of
235ergonomics, but significantly better compile-time error proofing than the others
236(except on par with `{fmt}` for errors).
237
238(2) Adding robust formatting would lead to less consistent structured data with
239essentially no additional benefit. Detailed field specifiers like `{.4f}` do not
240serve any purpose when the consumer is another computer program, and only
241minimal enhancement for developers. The typical utility formatting for
242hardware-facing usage is implemented (hex, binary, field-size).
243
244(3) The `{HEADER}` placeholders allow data to be placed in a human-friendly
245manner on par with `{fmt}`.
246
247(4) The call-site code generated by this API is almost identical to a `printf`
248and the journal-facing code is on similar performance footing to the
249journal_send APIs. We save some processing by using `iovec` interfaces and
250providing the source-code information, compared to the older `logging` APIs and
251have similar formatting performance to the printf-style formatting that
252journal_send used. The only difference is that this is done in our library
253rather than in `libsystemd`.
254
255Utilizing `{fmt}` for each structured data element would impose much greater
256overheads. Either we insert the `{fmt}` calls at the call-site (N calls plus N
257string objects for N structured data elements), or we do them in the library
258side where we lose the compile-time format checking. Also, the performance of
259the more robust formatting would almost certainly be worse, especially if we do
260the formatting library-side.
261
262Logging is done often. Shifting a few values onto the stack for a printf-type
263call compared to a kilobyte+ of generated code for inline `{fmt}` calls is a
264significant trade-off. And one with the only major advantage being more
265universally standardized API. The `lg2` API seems obvious enough in ergonomics
266such that this should not be an impediment to our community of developers.
267
268If it is later decided that we need more robust formatting or the `lg2::format`
269flags were a bad idea they could be deprecated and replaced. The format flags
270are a unique C++ type, which makes syntax parsing easier. As long as they are
271replaced with a similar unique C++ type both syntaxes could be supported for a
272time. Thus enhancing to support something like `fmt::arg` in the future could be
273done without impacting existing code usage. Also, an ambitious developer could
274write a Clang-Tidy code upgrader to transition from format flags to something
275else, like Abseil provides for API changes.
276
277> Doesn't duplicating the structured data in the message decrease the available
278> journal space?
279
280Far less than you might imagine. Journald keeps the messages in a compressed
281binary format. Since the data embedded in the message and the structured data
282are identical in content, and very near each other in the on-disk format, they
283compress exceptionally well. Likely on the order of 1-2 bytes per structured
284data element.
285
286The lack of data in the default `journalctl` output was a serious impediment to
287adoption of the `logging` API by some members of the development community.
288Unless we dispense with structured logging entirely, this duplication seems like
289a reasonable compromise.
290
291> Doesn't the `{HEADER}` syntax needlessly lengthen the message strings?
292
293Lengthen, yes. Needlessly, no?
294
295An earlier `lg2` proposal had a format flag that appended data to the message
296string instead of putting it in-place. The consensus was that this did not
297create as human-friendly messages as developers desired so the placeholder
298syntax was implemented instead.
299
300`{fmt}` can use shorter placeholders of `{}` or `{3}`. The non-indexed syntax
301would require structured data elements be in specific order and could be error
302prone with code maintenance. The indexed syntax is similarly error prone and
303harder to review. Both of them are more work for string formatting on the
304library.
305
306The `{HEADER}` syntax is identical to `{fmt}`'s "Named Argument" syntax but
307actually with better parameter ergonomics as `{fmt}` would require wrapping the
308named argument with a `fmt::arg` call, which is similar to `logging`'s `entry`.
309