Real time logging

Orocos

Table of Contents

Recent ML posts indicate the desire for a real-time (RT) capable logging framework, to supplement/replace the existing non-RT RTT::Logger. See http://www.orocos.org/forum/rtt/rtt-dev/logging-replacement for details.

NB Work in progress. Feedback welcomed

See https://www.fmtc.be/bugzilla/orocos/show_bug.cgi?id=708 for progress and patches.

Initial requirements

Approximately in order of priority (in my mind at least)

0) Completely disable all logging

1) Able log variable sized string messages

2) Able log from non-realtime and realtime code

3) Minimize (as reasonably practicable) the effect on runtime performance (eg minimize CPU cycles consumed)

4) Support different log levels

5) Support different "storage mediums" (ie able to log messages to file, to socket, to stdout)

Except for 3, and the "realtime" part of 2, the above is the functionality of the existing RTT::Logger

6) Support different log levels within a deployed system (ie able to log debug in one area, and info in another)

7) Support multiple storage mediums simultaneously at runtime

8) Runtime configuration of storage mediums and logging levels

9) Allow the user to extend the possible storage mediums at deployment-time (ie user can provide new storage class)

Optional IMHO

10) Support nested diagnostic contexts [1] [2] (a more advanced version of the Logger::In() that RTT's logger currently supports)

Logging framework

I see 3 basic choices, all of which are log4j ports (none of which support real-time right now)

log4cplus - does not appear to be maintained.
log4cxx - Apache license, well maintained, large, up to date functionality, heavy dependancies (APR, etc)
log4cpp - LGPL license, moderately maintained, medium size, fairly up to date (re log4j and logbook), no dependancies

I prefer 3) as it has the basic functionality we need, is license compatible, has a good design, and we've been offered developer access to modify it. I also think modifying a slightly less-well-known framework will be easier than getting some of our mod's in to log4cxx.

NOTE on the ML I was using the logback term logger, but log4cpp calls it a category. I am switching to category from now on!

Preliminary design

Add TLSF to RTT (a separate topic).

Fundamentally, replace std::string, wrap one class, and override two functions. :-)

Typedef/template in a real-time string to the logging framework, instead of std::string (also any std::map, etc).

Create an OCL::Category class derived from log4cpp::Category. Add an (optionally null) association to an RTT::BufferDataPort< log4cpp::LoggingEvent > (which uses rt_strings internally). Override the callAppenders() function to push to the port instead of directly calling appenders.

Modify the getCategory() function in the hierarchy maintainer to return our OCL:: Category instead of log4cpp::category. Alternatively, leave it producing log4cpp::category but contain that within the OCL::Category object (has-a instead of is-a relationship, in OO speak). The alternative is less modification to log4cpp, but worse performance and potentially more wrapping code.

Deployment

I have a working prototype of the OCL deployment for this (without the actual logging though), and it is really ugly. As in Really Ugly! To simplify the format and number of files involved, and reduce duplication, I suggest extending the OCL deployer to better support logging.

Sample system

Component C1 - uses category org.me.myapp
Component C2 - uses category org.me.myapp.c2
 
Appender A - console
Appender B - file
Appender C - serial
 
Logger org.me.myapp has level=info and appender A
Logger org.me.myapp.C2 has level=debug and appenders B, C

Configuration file for log4cpp

log4j.logger.org.me.myapp=info, AppA
log4j.logger.org.me.myapp.C2=debug, AppB, AppC
 
 
log4j.appender.AppA=org.apache.log4j.ConsoleAppender
log4j.appender.AppB=org.apache.log4j.FileAppender
log4j.appender.AppC=org.apache.log4j.SerialAppender
 
# AppA uses PatternLayout.
log4j.appender.AppA.layout=org.apache.log4j.PatternLayout
log4j.appender.AppA.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
# AppB uses SimpleLayout.
log4j.appender.AppB.layout=org.apache.log4j.SimpleLayout
# AppC uses PatternLayout with a different pattern from AppA
log4j.appender.AppC.layout=org.apache.log4j.PatternLayout
log4j.appender.AppC.layout.ConversionPattern=%d [%t] %-5p %c %x - %m%n

One possible Orocos XML deployer configuration

File: AppDeployer.xml

<struct name="ComponentC1" 
    ... />
<struct name="ComponentC2" 
    ... />
 
<struct name="AppenderA" type="ocl::ConsoleAppender"> 
    <simple name="PropertyFile" ...><value>AppAConfig.cpf</value></simple>
    <struct name="Peers"> <simple>Logger</simple>
</struct>
 
<struct name="AppenderB" type="ocl::FileAppender"> 
    <simple name="PropertyFile" ... />
    <struct name="Peers"> <simple>Logger</simple>
</struct>
 
<struct name="AppenderC" type="ocl::SerialAppender"> 
    <simple name="PropertyFile" ... />
    <struct name="Peers"> <simple>Logger</simple>
</struct>
 
<struct name="Logger" type="ocl::Logger"> 
    <simple name="PropertyFile" ...><value>logger.org.me.myapp.cpf</value></simple>
</struct>

File: AppAConfig.cpf

<properties>
  <simple name="LayoutClass" type="string"><value>ocl.PatternLayout</value>
  <simple name="LayoutConversionPattern" type="string"><value>%-4r [%t] %-5p %c %x - %m%n</value>
</properties>

… other appender .cpf files …

File: logger.org.me.myapp.cpf

<properties>
    <struct name="Categories" type="PropertyBag">
        <simple name="org.me.myapp" type="string"><value>info</value></simple>
        <simple name="org.me.myapp.C2" type="string"><value>debug</value></simple>
    </struct>
    <struct name="Appenders" type="PropertyBag">
        <simple name="org.me.myapp" type="string"><value>AppenderA</value></simple>
        <simple name="org.me.myapp.C2" type="string"><value>AppenderB</value></simple>
        <simple name="org.me.myapp.C2" type="string"><value>AppenderC</value></simple>
    </struct>
</properties>

The logger component is no more than a container for ports. Why special case this? Simply to make life easier for the deployer and to keep the deployer syntax and semantic model similar to what it currently is. A deployer deploys components - the only real special casing here is the connecting of ports (by the logger code) that aren't mentioned in the deployment file. If you use the existing deployment approach, you have to create a component per category, and mention the port in both the appenders and the category. This is what I currently have, and as I said, it is Really Ugly.

Example logger functionality (error checking elided)

Logger::configureHook()
 
    // create a port for each category with an appender
    for each appender in property bag
        find existing category
        if category not exist
            create category
            create port
            associate port with category
        find appender component
        connect category port with appender port
 
    // configure categories
    for each category in property bag
        if category not exist
            create category
        set category level

Important points

There will probably need to be a restriction that to maintain real-time, categories are found prior to a component being started (e.g. in configureHook() or startHook() ).

Note that not all OCL::Category objects contain a port. Only those category objects with associated appenders actually have a port. This is how the hierarchy works. If you have category "org.me.myapp.1.2.3" and it has no appenders but your log level is sufficient, then the logging action gets passed up the hierarchy. Say that category "org.me.myapp" has an appender (and that no logging level stops this logging action in the hierarchy in between), then that appender will actually log this event.

Also should create toolkit and transport plugins to deal with the log4cpp::LoggingEvent struct. This will allow for remote appenders, as well as viewing within the taskbrowser.

Port names would perhaps be something like "org.me.myapp.C1" => log_org_me_myapp_C1".

Real-Time Strings ?

It's not so much the string that needs to be real-time, but the stringstream, which converts our data (strings, ints,...) into a string buffer. Conveniently, the boost::iostream library allows with two lines of code to create a real-time string stream:

#include <boost/iostreams/device/array.hpp>
#include <boost/iostreams/stream.hpp>
 
namespace io = boost::iostreams;
 
int main()
{
  // prepare static sink
  const int MAX_MSG_LENGTH = 100;
  char sink[MAX_MSG_LENGTH];
  memset( sink, 0, MAX_MSG_LENGTH);
 
  // create 'stringstream' 
  io::stream<io::array_sink>  out(sink);
 
  out << "Hello World! "; // space required to avoid stack smashing abort.
 
  // close and flush stringstream
  out.close();
 
  // re-open from position zero.
  out.open( sink );
 
  // overwrites old data.
  out << "Hello World! ";
}

If user code 'only' uses const& to strings or C-strings, there is no need for rt_string, but for an rt_stringstream. The above code allows to realize that with a statically allocated (and non expandable!) char buffer. Replacing this buffer with a dynamically growing buffer will probably need an rt_string after all.

Unfortunately, the log4cpp::LoggingEvent is passed through RTT buffers, and this has std::string members. So, we need rt_string also, but rt_stringstream will be very useful also.

Warning For anyone using the boost::iostreams like above, either clear the array to 0's first, or ensure you explicitly write the string termination character ('\0'). The out << "..."; statement does not terminate the string otherwise. Also, I did not need the "space ... to avoid stack smashing abort" bit on Snow Leopard with gcc 4.2.1.

Using boost::iostream repeatedly ... you need to reset the stream between each use

#include <boost/iostreams/device/array.hpp>
#include <boost/iostreams/stream.hpp>
#include <boost/iostreams/seek.hpp>
 
namespace io = boost::iostreams;
 
...
 
char            str[500];
io::stream<io::array_sink>    ss(str);
 
ss << "cartPose_desi " << vehicleCartPosition_desi << '\0';
logger->debug(OCL::String(&str[0]));
 
// reset stream before re-using
io::seek(ss, 0, BOOST_IOS::beg);        
ss << "cartPose_meas " << vehicleCartPosition_meas << '\0';
logger->debug(OCL::String(&str[0]));

Problems/Questions/Issues

If before the Logger is configured (and hence, the buffer ports and appender associations are created), a component logs to a category, the logging event is lost. At that time no appenders exist. It also means that for any component that logs prior to configure time, by default, those logging events are lost. I think that this requires further examination, but would likely involve more change to the OCL deployer.

The logger configure code presumes that all appenders already exist. Is this an issue?

Is the port-category association a shared_ptr<port> style, or does the category simply own the port?

If the logger component has the ports added to it as well as to the category, then you could peruse the ports within the taskbrowser. Is this useful? If this is useful, is it worth making the categories and their levels available somehow for perusal within the taskbrowser?