This page collects notes and issues on the use of real-time logging. Its contents will eventually become the documentation for this feature.

This feature has been integrated in the Orocos 1.x and 2.x branches but is still considered under development. However, if you need a real-time logging infrastructure (ie text messages to users), this is exactly where you need to be. If you need a real-time data stream logging of ports, use the OCL's Reporting NetCDFReporting Component instead.

It is noted in the text where Orocos 1.x and 2.x differ.

Restrictions and issues

Restrictions

Startup the logging components first: Logging events prior to logging service's configure() will be dropped. The problem is that the logging service connects categories and appenders, and is it itself a component. So until it is configured, and the connections are all made, no appenders are available to deal with the event. Therefore you are suggested to put your appender components and the logging service in a separate deployment XML or script file which is loaded first. This will allow your application components to use logging from the start (component creation). See the ocl/logging/tests/data availablility XML deployment files for examples. OCL's deployer can execute in order multiple XML or script files.

Categories can not be created in real-time: They live on the normal heap via new/delete. Create all categories in your component's constructor or during configureHook() or similar.

NDC's are not supported. They involve std::string and std::vector which we currently can't replace.

Works only with OCL's deployers: If you use a non-deployer mechanism to bring up your system, you will need to add code to ensure that the log4cpp framework creates our OCL::Category objects, and not the default (non-real-time) log4cpp::Category objects. This should be done early in your application, prior to any components and categories being created.

Issues

On the ML it was requested to log when events have been lost. There are two places that this would need to be implemented, both annotated with TODO's in the code.

When creation of the OCL::String objects in a LoggingEvent exhausts the memory pool

When the buffer between a category and its appenders is full

This is not currently dealt with, but could be in future implementations.

In RTT/OCL 1.x, multiple appenders connected to the same category will, receive only some of the incoming logging events. This is as each appender will pop different elements from the category's buffer. This issue has been solved in 2.x.

The size of the buffer between a category and its appenders is currently fixed (see ocl/logging/Category.cpp). This will be fixed lateron on the 2.x branch. Note that that fixed size plus the default consumption rate of the FileAppender means you can exhaust the default TLSF memory pool in very short order. For a complex application (~40 components, 400 Hz cycle rate) we increased the default buffer size to 200, increased the memory pool to 10's of kilobytes (or megabytes) and increased the FileAppender consumption rate to 500 messages per second.

Viewing logs

We can use standard log viewers for Log4j in two ways:

Use FileAppender which writes log lines to a file and let the viewers read that file

Use Log4cxxAppender which creates a network socket to which Log4cxx/Log4j viewers can connect.

The deployer now defaults to a 20k real-time memory pool (see OCL CMake option ORO_DEFAULT_RTALLOC_SIZE), all Orocos RTT::Logger calls end up inside of log4cpp, and the default for RTT::Logger logging events is to log to a file "orocos.log". Same as always. But now you can configure all logging in one place!

IMPORTANT Be aware that there are two logging hierarchies at work here:

a non-real-time, log4cpp-based logging in use by RTT::Logger (currently only for RTT 1.x)

a real-time, OCL::Logging-based (with log4cpp underneath) in use by application code

In time, hopefully these two will evolve into just the latter.

Required Build flags

We're assuming here that you used 'orocreate-pkg' to setup a new application. So you're using the UseOrocos CMake macros.

Your application's manifest.xml must depend on ocl.

Your application's CMakeLists.txt must include the line : orocos_use_package(ocl-logging)

Both steps will make sure that your libraries link with the Orocos logging libraries and that include files are found.

See note at top of file regarding TLSF's bookkeeping overhead. The pool needs to be larger than that value.

Configuring RTT::Logger logging

NOTE: this feature is not available on the official release. Skip to the next section (Configuring OCL::logging) if you're not using the log4cpp branch of the RTT

You can use any of log4cpp's configurator approaches to configure, but the deployer's already know about PropertyConfigurator's. You can pass a log4cpp property file to the deployer and that will be used to configure the first of the hierarchies above - the non-real-time, logging used by RTT::Logger. For example

deployer-macosx --rtt-log4cpp-config-file /z/l/log4cpp.conf

where the file /z/l/log4cpp.conf is something like

# root category logs to application (this level is also the default for all # categories who's level is NOT explicitly set in this file)
log4j.rootCategory=DEBUG, applicationAppender
# orocos setup
log4j.category.org.orocos.rtt=INFO, orocosAppender
log4j.additivity.org.orocos.rtt=false# do not also log to parent categories
log4j.appender.orocosAppender=org.apache.log4j.FileAppender
log4j.appender.orocosAppender.fileName=orocos-log4cpp.log
log4j.appender.orocosAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.orocosAppender.layout.ConversionPattern=%d{%Y%m%dT%T.%l}[%-5p]%m%n

This configuration file simply changes the output filename and format. You could also add additional appenders (e.g. to stdout, to socket) and change the logging level for sub-categories, if RTT supported them (e.g. scripting.rtt.orocos.org).

IMPORTANT Note the direction of the category name, from org to rtt. This is specific to log4cpp and other log4j-style frameworks. Using a category "rtt.orocos.org" and sub-category "scripting.rtt.orocos.org" won't do what you, nor log4cpp, expect.

Configuring OCL::logging (XML)

This is how you would setup logging from a Deployer XML file. If you prefer to use a script, see the next section.

See ocl/logging/tests/xxx.xml for complete examples and more detail, but in short

IMPORTANT YOu must dynamic_cast to an OCL::logging::Category* to get the logger, as shown in the constructor above. Failure to do this can lead to trouble. You must also use explicitly use OCL::String() syntax when logging. Failure to do this produces compiler errors, as otherwise the system defaults to std::string and then you are no longer real-time. See the FAQ below for more description.

The last one is the most interesting. All RTT::Logger calls have been sent to the same appender as the application logs to. This means you can use the exact same logging statements in both your components (when they use OCL::Logging) and in your GUI code (when they use log4cpp directly). Less maintenance, less hassle, only one (more) tool to learn. The configuration file for the last example looks something like

# root category logs to application (this level is also the default for all # categories who's level is NOT explicitly set in this file)
log4j.rootCategory=DEBUG, applicationAppender
# orocos setup
log4j.category.org.orocos.rtt=INFO, applicationAppender
log4j.additivity.org.orocos.rtt=false# do not also log to parent categories# application setup
log4j.category.org.me=INFO, applicationAppender
log4j.additivity.org.me=false# do not also log to parent categories
log4j.category.org.me.gui=WARN
log4j.category.org.me.gui.Robot=DEBUG
log4j.category.org.me.gui.MainWindow=INFO
log4j.appender.applicationAppender=org.apache.log4j.FileAppender
log4j.appender.applicationAppender.fileName=application.log
log4j.appender.applicationAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.applicationAppender.layout.ConversionPattern=%d{%Y%m%dT%T.%l}[%-5p]%c %m%n

Technical details

There is a several kilobyte overhead for TLSF's bookkeeping (~3k on 32-bit Ubuntu, ~6k on 64-bit Snow Leopard). You must take this into account, although the standard OCL TLSF pool size (256k) should cover your needs.

Only the OCL::String (in 1.x) and RTT::rt_string (in 2.x) objects in OCL::logging::LoggingEvent objects use the real-time memory pool.

When you create a category, all parent categories up to the root are created. For example, "org.me.myapp.cat1" causes creation of five (5) categories: "org.me.myapp.cat1", "org.me.myapp", "org.me", "org", and "" (the root category) (presuming none of these already exist). These all occur on the normal heap (see below).

For real-time performance, ensure that TLSF is built with MMAP and SBRK support OFF in RTT's CMake options (-DOS_RT_MALLOC_MMAP=OFF -DOS_RT_MALLOC_SBRK=OFF).

TLSF use with multiple threads is currently supported only for non-macosx platforms. Use on macosx will exhibit (understandable) corruption in the TLSF bookkeeping (causes assert's).

FAQ

Logging statements are not recorded

Q: You are logging and everything seems fine, but you get no output to file/socket/stdout (depending on what your appender is).

A: Make sure you are using an OCL::logging::Category* and not a log4cpp::Category. The latter will silently compile and run, but it will discard all logging statements. This situation can also mask the fact that you are accidentally using std::string and not OCL::String. For example