logging: strip down and clean `log.h` and `log.c`
authorSimon Marchi <simon.marchi@efficios.com>
Mon, 11 Dec 2023 20:04:49 +0000 (15:04 -0500)
committerSimon Marchi <simon.marchi@efficios.com>
Thu, 14 Dec 2023 15:57:04 +0000 (10:57 -0500)
commit71436ae48cd2fcfcc59ae9a7da909e29a191145c
treedd0c406e568eb7edb369927f8572bdf1ca400e1d
parent78c888d139a40b58b10a2c92829cbb2c814ad766
logging: strip down and clean `log.h` and `log.c`

`log.h` slowly became a mix of the original zf_log [1] file and our own
changes over that.

I find that when I need to make changes to those files, I must consider
lots of features that we just never used and probably never will.
Amongst them are:

* Portability with MSVC and Android.

* Default values (`BT_LOG_DEF_*`).

* Tag prefix.

* Custom source location format.

* Censoring.

* All the global vs. local state, for example the global output level,
  all the BT_LOG*_AUX() macros.

* Library prefix (we just hardcoded `BT_` and `bt_` long ago).

* Mask of log message parts.

* Custom output callback.

Moreover, some of those features add execution time. For example,
logging always goes through vsnprintf(), even if you want to log a
simple string without any sophisticated formatting. Also, the actual
write() call is done through a callback because the output is
configurable. So is stuff like time formatting. We just don't need that.

This patch strips down those two files to make future changes easier. In
fact, it's pretty much a rewrite, but honors the current API, except for
the BT_LOG_WRITE*() functions (renamed, see below) and for
`BT_MINIMAL_LOG_LEVEL` which I renamed to `BT_LOG_MINIMAL_LEVEL` to keep
the same prefix.

This patch also moves everything which doesn't depend on user
definitions to `log-api.h`, and renames `log.c` to `log-api.c` for
consistency.

The user definitions are `BT_LOG_OUTPUT_LEVEL` and `BT_LOG_TAG`, which
you normally use as such:

    #define BT_LOG_OUTPUT_LEVEL my_level
    #define BT_LOG_TAG          "MY-TAG"
    #include "logging/log.h"

This gives access to BT_LOGI() and such which rely on those.

I think it's cleaner to separate the independent stuff. For example, not
that it's a true use case, but you could want to use the `log.h` macros
as well as another API which relies on `logging/log-api.h` at the same
time:

    #include "my-logger.hpp"

    #define BT_LOG_OUTPUT_LEVEL my_level
    #define BT_LOG_TAG          "MY-TAG"
    #include "logging/log.h"

Then an instance of some logger class in `my-logger.hpp` may have its
own independent output level and tag. Without this patch, you would need
to know that `my-logger.hpp` includes `logging/log.h` itself and
therefore make sure to define `BT_LOG_OUTPUT_LEVEL` and `BT_LOG_TAG`
before you include it:

    #define BT_LOG_OUTPUT_LEVEL my_level
    #define BT_LOG_TAG          "MY-TAG"
    #include "my-logger.hpp"

This works when you know it, but I believe it's less straightforward.

Now, the `log-api.h` interface is much simpler. The only mandatory
definition is `BT_LOG_MINIMAL_LEVEL`.

bt_log_write():
    Logs a message (no formatting).

bt_log_write_printf():
    Formats a message and logs it.

bt_log_write_mem():
    Logs a message (no formatting) and dumps a memory block.

bt_log_write_mem_printf():
    Formats a message, logs it, and dumps a memory block.

bt_log_write_errno():
    Logs an initial message, the string of the current `errno`, and
    a message (no formatting).

bt_log_write_errno_printf():
    Logs an initial message, the string of the current `errno`, and
    a formatted message.

All the functions above accept a file name, a function name, a line
number, a log level, and a tag. They log unconditionally, meaning they
don't check any current (run-time) log level. Use BT_LOG_ON_CUR_LVL() or
BT_LOG_ON() for that (unchanged).

All the BT_LOG_WRITE*() macros expand to calling the functions above. I
didn't change the BT_LOGT*(), BT_LOGD*(), BT_LOGI*(), BT_LOGW*(),
BT_LOGE*(), and BT_LOGF*() ones, but the BT_LOG_WRITE*() ones now have
`PRINTF` in their name when there's formatting (they didn't before):

* BT_LOG_WRITE_CUR_LVL()
* BT_LOG_WRITE()
* BT_LOG_WRITE_PRINTF_CUR_LVL()
* BT_LOG_WRITE_PRINTF()
* BT_LOG_WRITE_MEM_CUR_LVL()
* BT_LOG_WRITE_MEM()
* BT_LOG_WRITE_MEM_PRINTF_CUR_LVL()
* BT_LOG_WRITE_MEM_PRINTF()
* BT_LOG_WRITE_ERRNO_CUR_LVL()
* BT_LOG_WRITE_ERRNO()
* BT_LOG_WRITE_ERRNO_PRINTF_CUR_LVL()
* BT_LOG_WRITE_ERRNO_PRINTF()

Everything else is meant to work as before.

`log-api.c` is considerably simpler (than the previous `log.c`),
implementing exactly what we need in the project and no more. The only
output format is the current colored one (not configurable) and the only
destination is the standard error stream.

I did rewrite the memory block printing while being here. It used to
look like this:

    554889e5534883ec4864488b042528000000488945e831c04883ec086a17488d  UH??SH??HdH??%(???H?E?1?H???j?H?
    0520c900005068800000004c8d0dceffffff4c8d05f3c80000b903000000ba22  ? ???Ph????L??????L????????????"
    000000488d05e7c800004889c6488d05ecc800004889c7b800000000e8a6bb00  ???H??????H??H??????H???????????
    004883c420488d45d0be000000004889c7e88a090000488d45d04889c7e8e715  ?H?? H?E??????H???????H?E?H?????

and now looks like this:

    55 48 89 e5 53 48 83 ec 48 64 48 8b 04 25 28 00 | UH..SH..HdH..%(.
    00 00 48 89 45 e8 31 c0 48 83 ec 08 6a 17 48 8d | ..H.E.1.H...j.H.
    05 50 b9 00 00 50 6a 64 4c 8d 0d d1 ff ff ff 4c | .P...PjdL......L
    8d 05 26 b9 00 00 b9 03 00 00 00 ba 22 00 00 00 | ..&........."...
    48 8d 05 1a b9 00 00 48 89 c6 48 8d 05 15 b9 00 | H......H..H.....
    00 48 89 c7 b8 00 00 00 00 e8 98 ac 00 00 48 83 | .H............H.
    c4 20 48 8d                                     | . H.

I find that my version is more readable. The number of bytes/line is
fixed (16, like the default of `od` and `hexdump`).

I made the formatted date/time string cache much more simple, simply
using a TLS variable. Now it's just:

    struct date_time_cache {
        uint64_t s;
        uint32_t ms;
        char str[128];
    };

    static __thread struct date_time_cache date_time_cache = {0};

We're already using a TLS variable for the message buffer.

`log.c` used to call WriteFile(), GetLocalTime(), and
GetCurrentProcessId(), but I believe we have access to some MinGW magic
making it possible to call write(), gettimeofday(), and getpid(). The
TID part remains very platform-specific.

If we ever need new logging features, we can easily implement them, or
cherry-pick them from zf_log if they exist.

Project files are adapted here and there, mostly to match the few
renamed functions and macros.

[1]: https://github.com/wonder-mice/zf_log

Signed-off-by: Philippe Proulx <eeppeliteloop@gmail.com>
Change-Id: Icee002ccad33be0c610aeabfb39c4f8b1fe5ccb2
Reviewed-on: https://review.lttng.org/c/babeltrace/+/11398
Tested-by: jenkins <jenkins@lttng.org>
Reviewed-by: Simon Marchi <simon.marchi@efficios.com>
CI-Build: Simon Marchi <simon.marchi@efficios.com>
32 files changed:
configure.ac
src/Makefile.am
src/autodisc/autodisc.c
src/bindings/python/bt2/bt2/native_bt_autodisc.i.h
src/bindings/python/bt2/bt2/native_bt_component_class.i.h
src/bindings/python/bt2/bt2/native_bt_error.i.h
src/cli/babeltrace2.c
src/cli/logging.cpp
src/cli/logging.h
src/common/common.h
src/compat/mman.c
src/compat/socket.h
src/ctf-writer/assert-pre.h
src/lib/assert-cond-base.h
src/lib/assert-cond.c
src/lib/lib-logging.c
src/lib/logging.c
src/lib/logging.h
src/logging/comp-logging.h
src/logging/log-api.c [new file with mode: 0644]
src/logging/log-api.h [new file with mode: 0644]
src/logging/log.c [deleted file]
src/logging/log.h
src/plugins/ctf/common/metadata/ctf-meta-resolve.cpp
src/plugins/ctf/common/metadata/decoder.cpp
src/plugins/ctf/common/metadata/logging.cpp
src/plugins/ctf/fs-src/fs.cpp
src/plugins/ctf/fs-src/query.cpp
src/plugins/ctf/lttng-live/viewer-connection.cpp
src/python-plugin-provider/python-plugin-provider.c
src/string-format/format-error.c
tests/plugins/flt.lttng-utils.debug-info/test-bin-info.c
This page took 0.029559 seconds and 4 git commands to generate.