everest / liblog Goto Github PK

liblog uses boost's filter capabilities for e.g. allowing to configure log levels. It accesses fields such as Severity and Process, I suppose by use of "global attributes".

It is documented in everest-core's logging config file here:
https://github.com/EVerest/everest-core/blob/a5e4173d1726327cb22429bfbe0c65d3ed213b13/cmake/assets/logging.ini#L7-L12

# To get debug logs of only one module, add the "%Process% contains" filter, e.g.:
#
#     "(%Process% contains OCPP201 and %Severity% >= DEBG)"
#
# whereas "OCPP201" is the value of the field `active_modules.NAME.module` in the respective /config/config-*.yaml.
Filter="%Severity% >= INFO"

The documentation section

whereas "OCPP201" is the value of the field active_modules.NAME.module in the respective /config/config-*.yaml

is not correct, it does not work like this currently.

Somewhere along the way, both the actual OS process name and the process prefix of the logged line are changed. (I guess the OS process name is modified here in everest-framework, while the process name to log is modified in lib/logging.cpp in liblog.) Note also how the logged process name changes from active_modules.NAME to the truncated process name during the framework initialization. This logged process name is what is actually filtered on with %Process%, AFAICT.

So, one could say the documentation is incorrect, and change that to state active_modules.NAME, and fix the example. But this also doesn't work if that name is longer than 15 characters, due to liblog's truncation. (We have a serialcommhub_x7 instance name in our configs, and cannot filter on that.)

The ideal fix would be to separate the %Process% filter attribute from what is being logged. Or to introduce a new %ProcessFull% or %ProcessLong%, and handing it a concatenation of both the active_modules.NAME and active_modules.NAME.module, untruncated. (Perhaps concatenated with a :. Fun fact: boost apparently cannot have such a : in the Filter definition.) I hacked something like this locally which works great for the C++ modules, but doesn't pick up the node module's names.

I noticed that even though I set the logs to different levels, they always are shown at the info levels. For instance:

EVLOG_verbose << "verbose boop!";
EVLOG_debug << "debug boop!";
EVLOG_info << "info boop!";
EVLOG_warning << "warning boop!";

prints out as

[2024-05-17 17:32:31.427336] [0x0000ffff81207cc0] [info]    verbose boop!
[2024-05-17 17:32:31.427351] [0x0000ffff81207cc0] [info]    debug boop!
[2024-05-17 17:32:31.427352] [0x0000ffff81207cc0] [info]    info boop!
[2024-05-17 17:32:31.427354] [0x0000ffff81207cc0] [info]    warning boop!