Using real-time logging

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. 

    log4cpp::HierarchyMaintainer::set_category_factory(
        OCL::logging::Category::createOCLCategory);

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:

  1. Use FileAppender which writes log lines to a file and let the viewers read that file
  2. Use Log4cxxAppender which creates a network socket to which Log4cxx/Log4j viewers can connect.

These log viewers are compatible:

Complete application example

As at October 2010, assumes you are using for RTT 1.x:

And for RTT 2.x, use the Orocos Toolchain 2.2 or later from :

then build in the following order, with these options ON:

  • log4cpp (default options)
  • RTT: ENABLE_RT_MALLOC, OS_RT_MALLOC
  • OCL: BUILD_RTALLOC, BUILD_LOGGING

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:

  1. a non-real-time, log4cpp-based logging in use by RTT::Logger (currently only for RTT 1.x)
  2. 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.

  1. Your application's manifest.xml must depend on ocl.
  2. 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.

Configuring real-time memory pool size

The deployer's have command line options for this 

deployer-macosx --rtalloc-mem-size 10k
deployer-corba-macosx --rtalloc-mem-size 30m
deployer-corba-macosx --rtalloc 10240      # understands shortened, but unique, options
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 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE properties SYSTEM "cpf.dtd">
<properties>
 
  <simple name="Import" type="string">
    <value>liborocos-logging</value>
  </simple>
  <simple name="Import" type="string">
    <value>libTestComponent</value>
  </simple>
 
  <struct name="TestComponent" type="OCL::logging::test::Component">
    <struct name="Activity" type="Activity">
      <simple name="Period" type="double"><value>0.5</value></simple>
      <simple name="Priority" type="short"><value>0</value></simple>
      <simple name="Scheduler" type="string"><value>ORO_SCHED_OTHER</value></simple>
    </struct>
    <simple name="AutoConf" type="boolean"><value>1</value></simple>
    <simple name="AutoStart" type="boolean"><value>1</value></simple>
  </struct>
 
  <struct name="AppenderA" type="OCL::logging::FileAppender">
    <struct name="Activity" type="Activity">
      <simple name="Period" type="double"><value>0.5</value></simple>
      <simple name="Priority" type="short"><value>0</value></simple>
      <simple name="Scheduler" type="string"><value>ORO_SCHED_OTHER</value></simple>
    </struct>
    <simple name="AutoConf" type="boolean"><value>1</value></simple>
    <simple name="AutoStart" type="boolean"><value>1</value></simple>
    <struct name="Properties" type="PropertyBag">
      <simple name="Filename" type="string"><value>appendera.log</value></simple>
      <simple name="LayoutName" type="string"><value>pattern</value></simple>
      <simple name="LayoutPattern" type="string"><value>%d [%t] %-5p %c %x - %m%n</value></simple>
    </struct>
  </struct>
 
  <struct name="LoggingService" type="OCL::logging::LoggingService">
    <struct name="Activity" type="Activity">
      <simple name="Period" type="double"><value>0.5</value></simple>
      <simple name="Priority" type="short"><value>0</value></simple>
      <simple name="Scheduler" type="string"><value>ORO_SCHED_OTHER</value></simple>
    </struct>
 
    <simple name="AutoConf" type="boolean"><value>1</value></simple>
    <simple name="AutoStart" type="boolean"><value>1</value></simple>
 
    <struct name="Properties" type="PropertyBag">
      <struct name="Levels" type="PropertyBag">
        <simple name="org.orocos.ocl.logging.tests.TestComponent" 
                type="string"><value>info</value></simple>
      </struct>
 
      <struct name="Appenders" type="PropertyBag">
        <simple name="org.orocos.ocl.logging.tests.TestComponent" 
                type="string"><value>AppenderA</value></simple>
      </struct>
    </struct>
 
    <struct name="Peers" type="PropertyBag">
      <simple type="string"><value>AppenderA</value></simple>
    </struct> 
 
  </struct>
 
</properties>
which creates one component that logs to a org.orocos.ocl.logging.tests.TestComponent category, and that category is connected to one appender that logs to a file appendera.log.

Run this XML file, save it in 'setup_logging.xml' and use it: 

  deployer-gnulinux -s setuplogging.xml

Configuring OCL::logging (Lua)

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

require("rttlib")
 
-- Set this to true to write the property files the first time.
write_props=false
 
tc = rtt.getTC()
depl = tc:getPeer("deployer")
 
-- Create components. Enable BUILD_LOGGING and BUILD_TESTS for this to
-- work.
depl:loadComponent("TestComponent","OCL::logging::test::Component")
depl:setActivity("TestComponent", 0.5, 0, 0)
 
depl:loadComponent("AppenderA", "OCL::logging::FileAppender")
depl:setActivity("AppenderA", 0.5, 0, 0)
 
depl:loadComponent("LoggingService", "OCL::logging::LoggingService")
depl:setActivity("LoggingService", 0.5, 0, 0)
 
test = depl:getPeer("TestComponent")
aa = depl:getPeer("AppenderA")
ls = depl:getPeer("LoggingService")
 
depl:addPeer("AppenderA","LoggingService")
 
-- Load marshalling service to read/write components
depl:loadService("LoggingService","marshalling")
depl:loadService("AppenderA","marshalling")
 
if write_props then
   ls:provides("marshalling"):writeProperties("logging_properties.cpf")
   aa:provides("marshalling"):writeProperties("appender_properties.cpf")
   print("Wrote property files. Edit them and set write_props=false")
   os.exit(0)
else
   ls:provides("marshalling"):loadProperties("logging_properties.cpf")
   aa:provides("marshalling"):loadProperties("appender_properties.cpf")
end
 
test:configure()
aa:configure()
ls:configure()
 
test:start()
aa:start()
ls:start()

To run this script, save it in 'setup_logging.lua' and do: 

rttlua-gnulinux -i setup_logging.lua

Using OCL::Logging in C++

The component itself uses logging like the following simplified example 
// TestComponent.hpp
#include <ocl/LoggingService.hpp>
#include <ocl/Category.hpp>
 
class Component : public RTT::TaskContext
{
...
    /// Our logging category
    OCL::logging::Category* logger;
};
// TestComponent.cpp
#include <rtt/rt_string.hpp>
 
Component::Component(std::string name) :
        RTT::TaskContext(name),
        logger(dynamic_cast<OCL::logging::Category*>(
                   &log4cpp::Category::getInstance("org.orocos.ocl.logging.tests.TestComponent")))
{
}
 
bool Component::startHook()
{
    bool ok = (0 != logger);
    if (!ok)
    {
        log(Error) << "Unable to find existing OCL category '" << categoryName << "'" << endlog();
    }
 
    return ok;
}
 
void Component::updateHook()
{
    // RTT 1.X
    logger->error(OCL::String("Had an error here"));
    logger->debug(OCL::String("Some debug data ..."));
    // RTT 2.X
    logger->error(RTT::rt_string("Had an error here"));
    logger->debug(RTT::rt_string("Some debug data ..."));
    logger->getRTStream(log4cpp::Priority::DEBUG) << "Some debug data and a double value " << i;
}

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.

And the output of the above looks something like this: 

// file orocos.log, from RTT::Logger configured with log4cpp
20100414T09:50:11.844 [INFO] ControlTask 'HMI' found CORBA Naming Service.
20100414T09:50:11.845 [WARN] ControlTask 'HMI' already bound to CORBA Naming Service.
and from a deployer with OCL::logging (note that here the categories are set as components.something) 
20100414T21:41:22.539 [INFO ] components.HMI Started servicing::HMI
20100414T21:41:23.039 [DEBUG] components.Robot Motoman robot started
20100414T21:41:42.539 [INFO ] components.ConnectionMonitor Connected
and if you combine RTT::Logger and your own log4cpp-logging, say in a GUI application 
20100414T21:41:41.982 [INFO ] org.orocos.rtt Thread created with scheduler type '1', priority 0 and period 0.
20100414T21:41:41.982 [INFO ] org.orocos.rtt Creating Proxy interface for HMI
20100414T21:41:42.016 [DEBUG] org.me.myapp Connections made successfully
20100414T21:41:44.595 [DEBUG] org.me.myapp.Robot Request position hold

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

  • We rely on a real-time allocator called TLSF.
  • 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).
  • Currently, exhausting the real-time memory pool results in logging events being silently dropped (also, see next item).
  • 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

log4cpp::Category* logger = log4cpp::Category::getInstance(name);
logger->debug("Hello world")
When the above is used within the OCL real-time logging framework, no logging statements are recorded and it is not running in real-time. Changing the above to

OCL::logging::Category* logger = 
  dynamic_cast<OCL::logging::Category*>(&log4cpp::Category::getInstance(name));
logger->debug("Hello world")
will cause a compile error of 
/path/to/log4cpp/include/log4cpp/Category.hh: In member function ‘virtual bool MyComponent::configureHook()’:
/path/to/log4cpp/include/log4cpp/Category.hh:310: error: ‘void log4cpp::Category::debug(const char*, ...)’ is inaccessible
/path/to/my/source/MyComponent.cpp:64: error: within this context
because the "Hello world" string is being treated as a std::string, which you can not use with OCL::logging::Category. Finally, correct the code to

OCL::logging::Category* logger = 
  dynamic_cast<OCL::logging::Category*>(&log4cpp::Category::getInstance(name));
logger->debug(OCL::String("Hello world"))
and the code compiles and runs, and now logging statements are recorded.