Replace the "`LOGGER`" logging system with a full-featured logging library, e.g. `log4cplus`

Brief summary of issue

The "LOGGER" logging system is limited and tightly coupled with the rpcsvc daemon. In order to implement some functionalities (standalone programs, log level change at runtime, ...) and to guarantee maintainability it may be time to move to a full-featured logging system.

Types of issue

[ ] Bug report (report an issue with the code)
[x] Feature request (request for change which adds functionality)

Expected Behavior

The following points should be taken into consideration while choosing a new solution:

The functions and functors provided inside the ctp7_modules should be usable in standalone programs.
The log level should be changeable at runtime. See this issue #134.
The ATCA rpcsvc equivalent might not provide the "LOGGER" logging system.

Current Behavior

The logging system is tightly coupled with the rpcsvc daemon.

Context (for feature requests)

@jsturdy was trying to write standalone programs for the CTP7 and faced linking issues.

Moreover the templated RPC refactoring starts to decouple the ctp7_modules from the rpcsvc server so it is the perfect time to change the logging system.

Proposal

Since xDAQ and xHAL already use the log4cplus library I would suggest to use it as well on the CTP7. It is already compiled for arm and it would provide a common logging pattern.

A minimal example which logs to the CTP7 syslog daemon is trivial to write :

#include <log4cplus/logger.h>
#include <log4cplus/configurator.h>
#include <log4cplus/loggingmacros.h>

int main(int, const char**)
{
    log4cplus::initialize();
    log4cplus::PropertyConfigurator::doConfigure("log.properties");
    log4cplus::Logger logger = log4cplus::Logger::getInstance(LOG4CPLUS_TEXT("main"));

    LOG4CPLUS_WARN(logger, LOG4CPLUS_TEXT("Hello, World!"));

    return 0;
}

with the following log.properties file:

log4cplus.appender.syslog=log4cplus::SysLogAppender
log4cplus.appender.syslog.ident=syslog
log4cplus.appender.syslog.facility=user
log4cplus.appender.syslog.layout=log4cplus::TTCCLayout

log4cplus.rootLogger=DEBUG,syslog

and with the following compilation command:

$ arm-linux-gnueabihf-g++ --sysroot=${PETA_STAGE} main.cpp -llog4cplus

Special care will have to be taken when initializing the library inside the RPC modules since they are all loaded independently. The best place would be inside the rpcsvc daemon where the "LOGGER" logging system is initialized.

(copied from @lpetre-ulb's comment on mattermost) Hi @jsturdy, I was starting with the log4cplus release chosen by xDAQ and its upstream spec file (with additional hints from the gembuild template spec file) on the ULB setup. Building native RPMs is trivial and cross-compiling is not more complicated. However when it comes to cleanly cross-building RPMs, it is harder. The are two main reasons:

The spec files don't seem to be designed for cross-building (at least not with an external toolchain like the Xilinx's): BuildArch cannot be used, the %_arch variable/macro is not defined, ...
The installation path is different for the CTP7 package and the devel package installed on the development machine. So far, if I don't want to copy files by hand, the only solution I found is to create two spec files and build the library twice.

Nevertheless it more or less works now.

Though, the integration into the xHAL build system was not very clear... but I just saw you recently added a lot of documentation. :-) In the end I think we could follow the xDAQ structure with its external directory. The main question I have left before following that path is the following. Should I mimic the current copy-based system or, what I'd prefer, fully use the spec file with the library compilation done in %build?

and its upstream spec file (with additional hints from the gembuild template spec file)

link please?

a few questions/comments to scope this issue: 1) we're only discussing this for packaging extern for the ctp7, right (effectively, all the necessary tools that are in the xcompile folder)? -- ignore the devel package 2) with the patch provided by @lmoureau, we can now build xhal with either 1.2 or 2.0 log4cplus, right? 2.a) if that's the case, are features needed from the 2.0 API to get the transition to log4cplus in xhal(arm)/ctp7_modules? 2.b) if not, then just ignore for now the packaging question because there is a compatible log4cplus on both sides, and there is no requirement that they be the same version (of course, if this statement is false, we revisit, but then we just address point 1)

and its upstream spec file (with additional hints from the gembuild template spec file)

link please?

I was referring to this spec file in the upstream project and this one in the gembuild repository.

a few questions/comments to scope this issue:

1. we're only discussing this for packaging `extern` for the `ctp7`, right (effectively, all the necessary tools that are in the `xcompile` folder)? -- ignore the devel package

Currently log4cplus is compiled in xhal/xcompile, manually installed in the Peta Linux sysroot and manually copied to the CTP7. I think we can (should?) do better and provide RPMs for both the CTP7 and the development machine. This is not high priority, though

2. with the patch provided by @lmoureau, we can now build `xhal` with either 1.2 or 2.0 `log4cplus`, right?

As soon as it is merged, yes.

   2.a) if that's the case, are features needed from the 2.0 API to get the transition to `log4cplus` in `xhal(arm)`/`ctp7_modules`?

Since I don't want to create loggers by hand, but prefer to use a configuration file, the 1.2 and 2.0 APIs look compatible.

   2.b) if not, then just ignore for now the packaging question because there _is_ a _compatible_ `log4cplus` on both sides, and there is _no_ requirement that they be the same version (of course, if this statement is false, we revisit, but then we just address point 1)

Indeed there is no requirements that they share the same version. However I think it is better to start with a library that fully supports C++11 and above.

After a few benchmarks, log4cplus appears to be as fast as the LOGGER system. Even slightly faster and that could maybe be improved with a multi-threaded log4cplus build. Messages with a log level less than current log level have a near to zero cost, so providing a lot of debug information is possible.

Also, the library is loaded only once for all RPC modules. Unfortunately the logger hierarchy must be reinitialized for each module.

Before creating a PR, I would have a few questions :

Where should the configuration file be located? I was thinking of /mnt/pesistent/gemdaq/etc.
How do we define the logger names? Since log4cplus works with a hierarchy of loggers we could leverage that feature. For example, it allows different log levels for different parts of the program.
Finally, before porting all the modules to log4cplus, I think we should define a policy for the log levels.

After a few benchmarks, log4cplus appears to be as fast as the LOGGER system. Even slightly faster and that could maybe be improved with a multi-threaded log4cplus build. Messages with a log level less than current log level have a near to zero cost, so providing a lot of debug information is possible.

Also, the library is loaded only once for all RPC modules. Unfortunately the logger hierarchy must be reinitialized for each module.

What are the implications of this? Is this fundamentally different than the current LOGGER system?

Before creating a PR, I would have a few questions :
1. Where should the configuration file be located? I was thinking of `/mnt/persistent/gemdaq/etc`.

This is reasonable to me. Do we envision the log config being packaged with the xhal library, the ctp7_modules, both? Is the expectation that this log config will be modified on the card outside of a package update? Is there a hierarchy of locations that log4cplus will look for a config?

2. How do we define the logger names? Since `log4cplus` works with a hierarchy of loggers we could leverage that feature. For example, it allows different log levels for different parts of the program.

Can you post some output of logs coming in from various places? What were you thinking viz the names? If I understand the model correctly, each time a logger is created, it would have the option of creating a new logger (with a potentially different log level), or obtaining an existing logger from the service (using the set log level).

3. Finally, before porting all the modules to `log4cplus`, I think we should define a [policy for the log levels](https://github.com/cms-gem-daq-project/ctp7_modules/issues/134).

Is this not sufficient? In cmsgemos there are fewer levels, but the policy is effectively the same.

After a few benchmarks, log4cplus appears to be as fast as the LOGGER system. Even slightly faster and that could maybe be improved with a multi-threaded log4cplus build. Messages with a log level less than current log level have a near to zero cost, so providing a lot of debug information is possible. Also, the library is loaded only once for all RPC modules. Unfortunately the logger hierarchy must be reinitialized for each module.

What are the implications of this? Is this fundamentally different than the current LOGGER system?

The LOGGER system is initialized once per rpcsvc process, after the fork. The module name is set at each RPC method call. And the messages are produced and sent to the logger whichever is the current log level since the function is defined in another binary (rpcsvc).

The log4cplus library provides macros which decide to produce the message only if the log level is higher than the current log level. We don't really have a way to set the module name with log4cplus but it is possible to store the "pretty" function name with the PatternLayout.

What is fundamentally different is that we can only initialize the log system in module_init. While the initialization is internally protected with a static variable, the configuration must be reset and recreated for each module. This (1) blocks until all pending logs are flushed and (2) resets the configuration. In our case, the implications are minimal, since we load all modules at once and we don't use threads.

Do we envision the log config being packaged with the xhal library, the ctp7_modules, both?

It makes much more sense to package the config with the ctp7_modules since the loggers are initialized in the RPC modules. Moreover, xhal cannot predict how the logging will be used in the modules.

Still about xhal, we might want to change the logger initialization, at least for the XMLParser, since currently the log output to the console is hard-coded.

Is the expectation that this log config will be modified on the card outside of a package update?

Yes, it can happen during a debugging session for example. The default configuration might be to send logs to the local syslog with a log level of INFO, but during debugging one might want to store the logs up to DEBUG into a local file.

Is there a hierarchy of locations that log4cplus will look for a config?

Not by default, this is a feature we can implement though. Also, the config files support include statements and environment variables.

Can you post some output of logs coming in from various places?

Here is a minimal example with to RPC modules and two RPC methods (TestTemplatedRPC::MyMethod and TestLog::MyMethod). The PatternLayout must be improved for our use case but it shows some of the possibilities.

Aug 21 23:07:08 CTP7 user.info syslog_test: [void module_init(ModuleManager*)] INFO  - Hello, World!
Aug 21 23:07:08 CTP7 user.info syslog_test: [void module_init(ModuleManager*)] INFO  - Hello, World!
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestTemplatedRPC::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 0
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestTemplatedRPC::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 1
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestTemplatedRPC::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 2
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestTemplatedRPC::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 3
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestTemplatedRPC::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 4
[...]
Aug 21 23:07:08 CTP7 user.warn syslog_test: [void TestTemplatedRPC::MyMethod::operator()(uint32_t) const] WARN  - 0.00583161s
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestLog::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 0
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestLog::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 1
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestLog::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 2
Aug 21 23:07:08 CTP7 user.info syslog_test: [void TestLog::MyMethod::operator()(uint32_t) const] INFO  - Hello, World! 3
[...]

If I understand the model correctly, each time a logger is created, it would have the option of creating a new logger (with a potentially different log level), or obtaining an existing logger from the service (using the set log level).

log4cplus maintains a (or many) hierarchy of loggers which can be retrieved from the global instance. If the logger exists it the hierarchy it is returned, if it does not it is created on the fly.

For example,

log4cplus::Logger logger = log4cplus::Logger::getInstance(LOG4CPLUS_TEXT("test_log.init"));

retrieve the logger init in the branch test_log. The default logger configuration is provided by the configuration file. If it does not exist in the configuration, the first existing parent configuration is chosen. All loggers can be configured independently.

What were you thinking viz the names?

Since the precise function name (__PRETTY_FUNCTION__) can be (and currently is) logged, I see little use for the different loggers. However they can be interesting for specific usages of the code since it allows to send the logs to different places on demand.

I would use by default the root logger. I also would use a specific logger for tracing all readReg and writeReg calls. xhal may also deserves its own logger inside the ctp7_modules. Also one specific logger could be use for dumps so that it is possible to store them in a (possibly rolling) file in a precise format.

In the end it really is a case-by-case choice. The more loggers we have, the more versatile the configuration can be, but the more complex the system is.

Is this not sufficient?

These are the log levels used by syslog and the LOGGER system. Since we move to log4cplus, we have to use the same log levels as cmsgemos. I was thinking that the LOGGER log levels even have a too small granularity between some log levels. The log4cplus/cmsgemos log levels are clearer.

In cmsgemos there are fewer levels, but the policy is effectively the same.

Ok, but what is the policy? The meaning of each log level seems clear, but what information must always be logged in INFO for example?

Still about xhal, we might want to change the logger initialization, at least for the XMLParser, since currently the log output to the console is hard-coded.

Agreed.

Yes, it can happen during a debugging session for example. The default configuration might be to send logs to the local syslog with a log level of INFO, but during debugging one might want to store the logs up to DEBUG into a local file.

Sure, but this can be also controlled at run-time (well, maybe less easily over RPC...) a la how the xdaq process changes log level on-the-fly. But this question was really only for packaging purposes, so isn't critical for getting this done.

Ok, but what is the policy? The meaning of each log level seems clear, but what information must always be logged in INFO for example?

OK, better understand your question now. I don't think that having this policy written in stone is critical (at least for the initial stage); I don't have a strong feeling for mandating what must appear in an INFO message. I think it's not unreasonable to hone this over time (I don't expect that developers will wildly abuse the current levels with the info listed in the two links above, and bad behaviour can be corrected in PR review and added to guidelines)

I think I've parsed your reply and responded to your questions (in general, I have no objections to your proposal). If there's anything further, please draw my attention to it

cms-gem-daq-project / ctp7_modules