OCL logging - message order

We've been using OCL::Logging for a while and for the most part have been pretty pleased. One semi-major issue I've noticed is that our log messages don't always appear on screen or in-file in the order they were created. I can understand different component's log messages being woven together like a deck of cards being shuffled, but we're seeing log messages from the same component out of order. Is that expected? Is there a way to fix it?

If it helps diagnose the issue, here's our basic set up. We have a base class "LoggableComponent" that defines a logging category (parentCategory+name) and has a member named 'logger' that is assigned with a dynamic_cast to the OCL category. Then our components inherit from LoggableComponent and make log calls like "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure is deployed using a Lua script and CPF files. We deploy one FileAppender, one OstreamAppender, and one LoggingService. Both appenders have a "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender and LoggingService run at 0.01s.

--
Dustin Gooding
NASA/JSC Robotics

OCL logging - message order

Hi Dustin,

On Fri, Apr 19, 2013 at 4:25 PM, Gooding, Dustin R. (JSC-ER411) <
dustin [dot] r [dot] gooding [..] ...> wrote:

> We've been using OCL::Logging for a while and for the most part have been
> pretty pleased. One semi-major issue I've noticed is that our log messages
> don't always appear on screen or in-file in the order they were created. I
> can understand different component's log messages being woven together like
> a deck of cards being shuffled, but we're seeing log messages from the same
> component out of order. Is that expected? Is there a way to fix it?
>
> If it helps diagnose the issue, here's our basic set up. We have a base
> class "LoggableComponent" that defines a logging category
> (parentCategory+name) and has a member named 'logger' that is assigned with
> a dynamic_cast to the OCL category. Then our components inherit from
> LoggableComponent and make log calls like
> "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure
> is deployed using a Lua script and CPF files. We deploy one FileAppender,
> one OstreamAppender, and one LoggingService. Both appenders have a
> "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender
> and LoggingService run at 0.01s.
>

First of all, the OstreamAppender ignores the MaxEventsPerCycle property
and will just get 1 event every cycle. Second, the LoggingService doesn't
need to run actually (only configure, no start), it's a passive component.
Third, if you happened to configure the LoggingService twice, you might get
double messages, although that doesn't explain your issue probably.

I fixed the above issues in the attached patches, but in the end, I can't
see any source for out-of-order messages, except for the appender itself in
log4cpp...which I didn't check yet.

Maybe you could check that:
- you did not accidentally create two file or ostream appenders
- you didn't configure the loggingservice component twice.

The latter would be fixed in the patches though.

Is the out-of-order in both ostream and file appenders or only one of them ?

Peter

OCL logging - message order

On Apr 19, 2013, at 10:25 , Gooding, Dustin R. (JSC-ER411) wrote:

> We've been using OCL::Logging for a while and for the most part have been pretty pleased. One semi-major issue I've noticed is that our log messages don't always appear on screen or in-file in the order they were created. I can understand different component's log messages being woven together like a deck of cards being shuffled, but we're seeing log messages from the same component out of order. Is that expected? Is there a way to fix it?
>
> If it helps diagnose the issue, here's our basic set up. We have a base class "LoggableComponent" that defines a logging category (parentCategory+name) and has a member named 'logger' that is assigned with a dynamic_cast to the OCL category. Then our components inherit from LoggableComponent and make log calls like "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure is deployed using a Lua script and CPF files. We deploy one FileAppender, one OstreamAppender, and one LoggingService. Both appenders have a "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender and LoggingService run at 0.01s.

We have a very similar structure, and I don't recall seeing out of order messages before (IIRC). We run our components and appenders at much higher rates though; most everything is near 500 Hz. We also don't use Lua, but it sounds like that is just in deployment setup for you. We do use multiple appenders, but at least one of the appenders has multiple components associated with it.

I _could_ see how one category used from multiple threads _might_ theoretically end up with out of order messages due to pre-emption. What kind of timing differences are we talking about? Are these microsecond level time deltas, or say tenths of a second?
S

OCL logging - message order

On Apr 19, 2013, at 10:51 AM, S Roderick <kiwi [dot] net [..] ...> wrote:

> On Apr 19, 2013, at 10:25 , Gooding, Dustin R. (JSC-ER411) wrote:
>
>> We've been using OCL::Logging for a while and for the most part have been pretty pleased. One semi-major issue I've noticed is that our log messages don't always appear on screen or in-file in the order they were created. I can understand different component's log messages being woven together like a deck of cards being shuffled, but we're seeing log messages from the same component out of order. Is that expected? Is there a way to fix it?
>>
>> If it helps diagnose the issue, here's our basic set up. We have a base class "LoggableComponent" that defines a logging category (parentCategory+name) and has a member named 'logger' that is assigned with a dynamic_cast to the OCL category. Then our components inherit from LoggableComponent and make log calls like "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure is deployed using a Lua script and CPF files. We deploy one FileAppender, one OstreamAppender, and one LoggingService. Both appenders have a "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender and LoggingService run at 0.01s.
>
> We have a very similar structure, and I don't recall seeing out of order messages before (IIRC). We run our components and appenders at much higher rates though; most everything is near 500 Hz. We also don't use Lua, but it sounds like that is just in deployment setup for you. We do use multiple appenders, but at least one of the appenders has multiple components associated with it.
>
> I _could_ see how one category used from multiple threads _might_ theoretically end up with out of order messages due to pre-emption. What kind of timing differences are we talking about? Are these microsecond level time deltas, or say tenths of a second?
> S

We didn't want to run our file appender at high rates, because we assumed that would be bad from a file I/O standpoint. Running our stream appender faster would be fine.

The timing differences are very close to each other. Take this (pretend) example:

/*
log("before");
doMethod();
log("after");

def doMethod()
{
log("inside1");
log("inside2");
}
*/

We could potentially get something like this in the logs:
/*
inside1
before
inside2
after
*/

My coworker just mentioned that he's even seen instances where "inside2" would come before "inside1" in the above (pretend) example.

Weird stuff…

-dustin

OCL logging - message order

On Apr 19, 2013, at 12:18 , Gooding, Dustin R. (JSC-ER411) wrote:

> On Apr 19, 2013, at 10:51 AM, S Roderick <kiwi [dot] net [..] ...> wrote:
>
>> On Apr 19, 2013, at 10:25 , Gooding, Dustin R. (JSC-ER411) wrote:
>>
>>> We've been using OCL::Logging for a while and for the most part have been pretty pleased. One semi-major issue I've noticed is that our log messages don't always appear on screen or in-file in the order they were created. I can understand different component's log messages being woven together like a deck of cards being shuffled, but we're seeing log messages from the same component out of order. Is that expected? Is there a way to fix it?
>>>
>>> If it helps diagnose the issue, here's our basic set up. We have a base class "LoggableComponent" that defines a logging category (parentCategory+name) and has a member named 'logger' that is assigned with a dynamic_cast to the OCL category. Then our components inherit from LoggableComponent and make log calls like "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure is deployed using a Lua script and CPF files. We deploy one FileAppender, one OstreamAppender, and one LoggingService. Both appenders have a "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender and LoggingService run at 0.01s.
>>
>> We have a very similar structure, and I don't recall seeing out of order messages before (IIRC). We run our components and appenders at much higher rates though; most everything is near 500 Hz. We also don't use Lua, but it sounds like that is just in deployment setup for you. We do use multiple appenders, but at least one of the appenders has multiple components associated with it.
>>
>> I _could_ see how one category used from multiple threads _might_ theoretically end up with out of order messages due to pre-emption. What kind of timing differences are we talking about? Are these microsecond level time deltas, or say tenths of a second?
>> S
>
> We didn't want to run our file appender at high rates, because we assumed that would be bad from a file I/O standpoint. Running our stream appender faster would be fine.

I don't think that it happens that way. If we have very high rate bursts, it just means that after finishing writing a number of events to disk, the appender comes back quickly to check for more work to do. Without that, we found that we had trouble keeping up with bursts.

> The timing differences are very close to each other. Take this (pretend) example:
>
> /*
> log("before");
> doMethod();
> log("after");
>
> def doMethod()
> {
> log("inside1");
> log("inside2");
> }
> */

That's Lua, right?

> We could potentially get something like this in the logs:
> /*
> inside1
> before
> inside2
> after
> */
>
> My coworker just mentioned that he's even seen instances where "inside2" would come before "inside1" in the above (pretend) example.
>
> Weird stuff…

Yeah, that's an understatement. I've never seen that within one component. Something is wrong ... Can you reproduce this with C++ logging calls?

Do you get _all_ logging events in both appenders? Do you have both the file and the ostream appender attached to the same category? If so, how did you modify OCL to support that (trunk currently doesn't)?
S

OCL logging - message order

On Apr 19, 2013, at 11:23 AM, Stephen Roderick <kiwi [dot] net [..] ...> wrote:

> On Apr 19, 2013, at 12:18 , Gooding, Dustin R. (JSC-ER411) wrote:
>
>> On Apr 19, 2013, at 10:51 AM, S Roderick <kiwi [dot] net [..] ...> wrote:
>>
>>> On Apr 19, 2013, at 10:25 , Gooding, Dustin R. (JSC-ER411) wrote:
>>>
>>>> We've been using OCL::Logging for a while and for the most part have been pretty pleased. One semi-major issue I've noticed is that our log messages don't always appear on screen or in-file in the order they were created. I can understand different component's log messages being woven together like a deck of cards being shuffled, but we're seeing log messages from the same component out of order. Is that expected? Is there a way to fix it?
>>>>
>>>> If it helps diagnose the issue, here's our basic set up. We have a base class "LoggableComponent" that defines a logging category (parentCategory+name) and has a member named 'logger' that is assigned with a dynamic_cast to the OCL category. Then our components inherit from LoggableComponent and make log calls like "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure is deployed using a Lua script and CPF files. We deploy one FileAppender, one OstreamAppender, and one LoggingService. Both appenders have a "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender and LoggingService run at 0.01s.
>>>
>>> We have a very similar structure, and I don't recall seeing out of order messages before (IIRC). We run our components and appenders at much higher rates though; most everything is near 500 Hz. We also don't use Lua, but it sounds like that is just in deployment setup for you. We do use multiple appenders, but at least one of the appenders has multiple components associated with it.
>>>
>>> I _could_ see how one category used from multiple threads _might_ theoretically end up with out of order messages due to pre-emption. What kind of timing differences are we talking about? Are these microsecond level time deltas, or say tenths of a second?
>>> S
>>
>> We didn't want to run our file appender at high rates, because we assumed that would be bad from a file I/O standpoint. Running our stream appender faster would be fine.
>
> I don't think that it happens that way. If we have very high rate bursts, it just means that after finishing writing a number of events to disk, the appender comes back quickly to check for more work to do. Without that, we found that we had trouble keeping up with bursts.
>
>> The timing differences are very close to each other. Take this (pretend) example:
>>
>> /*
>> log("before");
>> doMethod();
>> log("after");
>>
>> def doMethod()
>> {
>> log("inside1");
>> log("inside2");
>> }
>> */
>
> That's Lua, right?

Actually, it's just terrible psuedo-code. Apologies for not being clear.

>
>> We could potentially get something like this in the logs:
>> /*
>> inside1
>> before
>> inside2
>> after
>> */
>>
>> My coworker just mentioned that he's even seen instances where "inside2" would come before "inside1" in the above (pretend) example.
>>
>> Weird stuff…
>
> Yeah, that's an understatement. I've never seen that within one component. Something is wrong ... Can you reproduce this with C++ logging calls?
>
> Do you get _all_ logging events in both appenders? Do you have both the file and the ostream appender attached to the same category? If so, how did you modify OCL to support that (trunk currently doesn't)?
> S
>

This is all occurring using C++ components with a Lua deployment.

I guess I don't understand your question about multiple appenders connected to the same category. With our current set up, when we write a log message, it goes to both stdout and the our log file. They're formatted differently (based on the appender's configuration), but I believe all our log messages go to both destinations. We made no modifications to OCL to support this behavior. We're running the 2.6 debs.

Below is the relevant section of Lua deploy code, the CPF files used, and some snippets of C++ code that define the OCL::Logging categories.

-dustin

/** Lua deployment of OCL::Logging infrastructure

depl:loadComponent("LogFile", "OCL::logging::FileAppender")
depl:setActivity("LogFile", 0.1, 0, 0)

depl:loadComponent("LogConsole", "OCL::logging::OstreamAppender")
depl:setActivity("LogConsole", 0.01, 0, 0)

depl:loadComponent("LoggingService", "OCL::logging::LoggingService")
depl:setActivity("LoggingService", 0.01, 0, 0)

lf = depl:getPeer("LogFile")
lc = depl:getPeer("LogConsole")
ls = depl:getPeer("LoggingService")

depl:addPeer("LoggingService","LogFile")
depl:addPeer("LoggingService","LogConsole")

-- Load marshalling service to read/write components
depl:loadService("LoggingService","marshalling")
depl:loadService("LogFile","marshalling")
depl:loadService("LogConsole","marshalling")

ls:provides("marshalling"):loadProperties(path.."/share/logging_properties.cpf")
lf:provides("marshalling"):loadProperties(path.."/share/logFile_properties.cpf")
lc:provides("marshalling"):loadProperties(path.."/share/logConsole_properties.cpf")

ls:configure()
ls:start()

lf:configure()
lc:configure()

lf:start()
lc:start()

**/

/** logging_properties.cpf

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE properties SYSTEM "cpf.dtd">
<properties>
<struct name="Levels" type="PropertyBag">
<simple name="gov.nasa" type="string"><value>notice</value></simple>
</struct>
<struct name="Appenders" type="PropertyBag">
<simple name="gov.nasa" type="string"><value>LogFile</value></simple>
<simple name="gov.nasa" type="string"><value>LogConsole</value></simple>
</struct>
</properties>

**/

/** logFile_properties.cpf

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE properties SYSTEM "cpf.dtd">
<properties>
<simple name="LayoutName" type="string"><value>pattern</value></simple>
<simple name="LayoutPattern" type="string"><value>%d [%-5p] [%c] %m%n</value></simple>
<simple name="Filename" type="string"><value>orocos-log4cpp.log</value></simple>
<simple name="MaxEventsPerCycle" type="long"><value>100</value></simple>
</properties>

**/

/** logConsole_properties.cpf

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE properties SYSTEM "cpf.dtd">
<properties>
<simple name="LayoutName" type="string"><value>pattern</value></simple>
<simple name="LayoutPattern" type="string"><value>[%-5p] [%c{1}] %m%n</value></simple>
<simple name="MaxEventsPerCycle" type="long"><value>100</value></simple>
</properties>

**/

/** LoggableComponent snippets

//header
class LoggableComponent
{
public:
LoggableComponent(std::string const& name);
bool isLoggingReady();

static const std::string parentCategory;

protected:
std::string categoryName;
OCL::logging::Category* logger;
std::string name;
};

//source
const std::string LoggableComponent::parentCategory = "gov.nasa.";

LoggableComponent::LoggableComponent(std::string const& name) :
categoryName(parentCategory + name),
logger(dynamic_cast<OCL::logging::Category*>(
&log4cpp::Category::getInstance(categoryName))),
name(name)
{
}

**/

/** Example component snippets

//header
class ExampleComponent : public RTT::TaskContext, public LoggableComponent
{
public:
ExampleComponent(std::string const& name);

//source
ExampleComponent:: ExampleComponent(std::string const& name) :
TaskContext(name),
LoggableComponent(name)
{}

bool ExampleComponent::configureHook()
{
logger->debug(RTT::rt_string("ExampleComponent executes configureHook!"));
return true;
}

**/

OCL logging - message order

On Apr 19, 2013, at 15:08 , Gooding, Dustin R. (JSC-ER411) wrote:

> On Apr 19, 2013, at 11:23 AM, Stephen Roderick <kiwi [dot] net [..] ...> wrote:
>
>> On Apr 19, 2013, at 12:18 , Gooding, Dustin R. (JSC-ER411) wrote:
>>
>>> On Apr 19, 2013, at 10:51 AM, S Roderick <kiwi [dot] net [..] ...> wrote:
>>>
>>>> On Apr 19, 2013, at 10:25 , Gooding, Dustin R. (JSC-ER411) wrote:
>>>>
>>>>> We've been using OCL::Logging for a while and for the most part have been pretty pleased. One semi-major issue I've noticed is that our log messages don't always appear on screen or in-file in the order they were created. I can understand different component's log messages being woven together like a deck of cards being shuffled, but we're seeing log messages from the same component out of order. Is that expected? Is there a way to fix it?
>>>>>
>>>>> If it helps diagnose the issue, here's our basic set up. We have a base class "LoggableComponent" that defines a logging category (parentCategory+name) and has a member named 'logger' that is assigned with a dynamic_cast to the OCL category. Then our components inherit from LoggableComponent and make log calls like "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure is deployed using a Lua script and CPF files. We deploy one FileAppender, one OstreamAppender, and one LoggingService. Both appenders have a "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender and LoggingService run at 0.01s.
>>>>
>>>> We have a very similar structure, and I don't recall seeing out of order messages before (IIRC). We run our components and appenders at much higher rates though; most everything is near 500 Hz. We also don't use Lua, but it sounds like that is just in deployment setup for you. We do use multiple appenders, but at least one of the appenders has multiple components associated with it.
>>>>
>>>> I _could_ see how one category used from multiple threads _might_ theoretically end up with out of order messages due to pre-emption. What kind of timing differences are we talking about? Are these microsecond level time deltas, or say tenths of a second?
>>>> S
>>>
>>> We didn't want to run our file appender at high rates, because we assumed that would be bad from a file I/O standpoint. Running our stream appender faster would be fine.
>>
>> I don't think that it happens that way. If we have very high rate bursts, it just means that after finishing writing a number of events to disk, the appender comes back quickly to check for more work to do. Without that, we found that we had trouble keeping up with bursts.
>>
>>> The timing differences are very close to each other. Take this (pretend) example:
>>>
>>> /*
>>> log("before");
>>> doMethod();
>>> log("after");
>>>
>>> def doMethod()
>>> {
>>> log("inside1");
>>> log("inside2");
>>> }
>>> */
>>
>> That's Lua, right?
>
> Actually, it's just terrible psuedo-code. Apologies for not being clear.
>
>>
>>> We could potentially get something like this in the logs:
>>> /*
>>> inside1
>>> before
>>> inside2
>>> after
>>> */
>>>
>>> My coworker just mentioned that he's even seen instances where "inside2" would come before "inside1" in the above (pretend) example.
>>>
>>> Weird stuff…
>>
>> Yeah, that's an understatement. I've never seen that within one component. Something is wrong ... Can you reproduce this with C++ logging calls?
>>
>> Do you get _all_ logging events in both appenders? Do you have both the file and the ostream appender attached to the same category? If so, how did you modify OCL to support that (trunk currently doesn't)?
>> S
>>
>
> This is all occurring using C++ components with a Lua deployment.
>
> I guess I don't understand your question about multiple appenders connected to the same category. With our current set up, when we write a log message, it goes to both stdout and the our log file. They're formatted differently (based on the appender's configuration), but I believe all our log messages go to both destinations. We made no modifications to OCL to support this behavior. We're running the 2.6 debs.
>
> Below is the relevant section of Lua deploy code, the CPF files used, and some snippets of C++ code that define the OCL::Logging categories.
>
> -dustin

Nothing stands out in the code snippets you sent. All looks pretty vanilla, which is good.

My question re multiple appenders is that the OCL::Logging implementation that I initially built only supported _one_ appender per category (there's only one output buffer port in each OCL::Category). So I'm curious _how_ you got two appenders to successfully connect to the same category, as I don't recall anything on the ML about someone improving this implementation. Having said that, the version we are using is v1.10 based, so we are _way_ behind.

I can't even theorize how events from the same component, logging to the same category, end up out of order. Does this still occur if you only log to one appender? The chain of events is straight forward

1. component logs to category
2. category hierarchy is traversed, when one is found that should log, it pushes the event onto the RTT::BufferPort of that category
at some point later, an appender wakes up, finds a non-empty buffer, pops the contents, and then does whatever it needs to (e.ge. 3. write to file, write to console).

There aren't many places to break that. 1 and 2 occur in the logging component's thread, and so they can't be interrupted by the component itself. 3 occurs later, but it pops events in order. This really isn't that complicated, unless something significantly changed this in a port to v2?
S

>
>
> /** Lua deployment of OCL::Logging infrastructure
>
> depl:loadComponent("LogFile", "OCL::logging::FileAppender")
> depl:setActivity("LogFile", 0.1, 0, 0)
>
> depl:loadComponent("LogConsole", "OCL::logging::OstreamAppender")
> depl:setActivity("LogConsole", 0.01, 0, 0)
>
> depl:loadComponent("LoggingService", "OCL::logging::LoggingService")
> depl:setActivity("LoggingService", 0.01, 0, 0)
>
> lf = depl:getPeer("LogFile")
> lc = depl:getPeer("LogConsole")
> ls = depl:getPeer("LoggingService")
>
> depl:addPeer("LoggingService","LogFile")
> depl:addPeer("LoggingService","LogConsole")
>
> -- Load marshalling service to read/write components
> depl:loadService("LoggingService","marshalling")
> depl:loadService("LogFile","marshalling")
> depl:loadService("LogConsole","marshalling")
>
> ls:provides("marshalling"):loadProperties(path.."/share/logging_properties.cpf")
> lf:provides("marshalling"):loadProperties(path.."/share/logFile_properties.cpf")
> lc:provides("marshalling"):loadProperties(path.."/share/logConsole_properties.cpf")
>
> ls:configure()
> ls:start()
>
> lf:configure()
> lc:configure()
>
> lf:start()
> lc:start()
>
> **/
>
>
> /** logging_properties.cpf
>
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE properties SYSTEM "cpf.dtd">
> <properties>
> <struct name="Levels" type="PropertyBag">
> <simple name="gov.nasa" type="string"><value>notice</value></simple>
> </struct>
> <struct name="Appenders" type="PropertyBag">
> <simple name="gov.nasa" type="string"><value>LogFile</value></simple>
> <simple name="gov.nasa" type="string"><value>LogConsole</value></simple>
> </struct>
> </properties>
>
> **/
>
>
> /** logFile_properties.cpf
>
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE properties SYSTEM "cpf.dtd">
> <properties>
> <simple name="LayoutName" type="string"><value>pattern</value></simple>
> <simple name="LayoutPattern" type="string"><value>%d [%-5p] [%c] %m%n</value></simple>
> <simple name="Filename" type="string"><value>orocos-log4cpp.log</value></simple>
> <simple name="MaxEventsPerCycle" type="long"><value>100</value></simple>
> </properties>
>
> **/
>
>
> /** logConsole_properties.cpf
>
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE properties SYSTEM "cpf.dtd">
> <properties>
> <simple name="LayoutName" type="string"><value>pattern</value></simple>
> <simple name="LayoutPattern" type="string"><value>[%-5p] [%c{1}] %m%n</value></simple>
> <simple name="MaxEventsPerCycle" type="long"><value>100</value></simple>
> </properties>
>
> **/
>
>
> /** LoggableComponent snippets
>
> //header
> class LoggableComponent
> {
> public:
> LoggableComponent(std::string const& name);
> bool isLoggingReady();
>
> static const std::string parentCategory;
>
> protected:
> std::string categoryName;
> OCL::logging::Category* logger;
> std::string name;
> };
>
> //source
> const std::string LoggableComponent::parentCategory = "gov.nasa.";
>
> LoggableComponent::LoggableComponent(std::string const& name) :
> categoryName(parentCategory + name),
> logger(dynamic_cast<OCL::logging::Category*>(
> &log4cpp::Category::getInstance(categoryName))),
> name(name)
> {
> }
>
> **/
>
>
> /** Example component snippets
>
> //header
> class ExampleComponent : public RTT::TaskContext, public LoggableComponent
> {
> public:
> ExampleComponent(std::string const& name);
>
> //source
> ExampleComponent:: ExampleComponent(std::string const& name) :
> TaskContext(name),
> LoggableComponent(name)
> {}
>
> bool ExampleComponent::configureHook()
> {
> logger->debug(RTT::rt_string("ExampleComponent executes configureHook!"));
> return true;
> }
>
>
> **/

OCL logging - message order

On Fri, Apr 19, 2013 at 9:31 PM, Stephen Roderick <kiwi [dot] net [..] ...> wrote:

> On Apr 19, 2013, at 15:08 , Gooding, Dustin R. (JSC-ER411) wrote:
>
> > On Apr 19, 2013, at 11:23 AM, Stephen Roderick <kiwi [dot] net [..] ...> wrote:
> >
> >> On Apr 19, 2013, at 12:18 , Gooding, Dustin R. (JSC-ER411) wrote:
> >>
> >>> On Apr 19, 2013, at 10:51 AM, S Roderick <kiwi [dot] net [..] ...> wrote:
> >>>
> >>>> On Apr 19, 2013, at 10:25 , Gooding, Dustin R. (JSC-ER411) wrote:
> >>>>
> >>>>> We've been using OCL::Logging for a while and for the most part have
> been pretty pleased. One semi-major issue I've noticed is that our log
> messages don't always appear on screen or in-file in the order they were
> created. I can understand different component's log messages being woven
> together like a deck of cards being shuffled, but we're seeing log messages
> from the same component out of order. Is that expected? Is there a way to
> fix it?
> >>>>>
> >>>>> If it helps diagnose the issue, here's our basic set up. We have a
> base class "LoggableComponent" that defines a logging category
> (parentCategory+name) and has a member named 'logger' that is assigned with
> a dynamic_cast to the OCL category. Then our components inherit from
> LoggableComponent and make log calls like
> "logger->debug(RTT::rt_string("asdf"))". The OCL logging infrastructure
> is deployed using a Lua script and CPF files. We deploy one FileAppender,
> one OstreamAppender, and one LoggingService. Both appenders have a
> "MaxEventsPerCycle" of 100. FileAppender runs at 0.1s. OstreamAppender
> and LoggingService run at 0.01s.
> >>>>
> >>>> We have a very similar structure, and I don't recall seeing out of
> order messages before (IIRC). We run our components and appenders at much
> higher rates though; most everything is near 500 Hz. We also don't use Lua,
> but it sounds like that is just in deployment setup for you. We do use
> multiple appenders, but at least one of the appenders has multiple
> components associated with it.
> >>>>
> >>>> I _could_ see how one category used from multiple threads _might_
> theoretically end up with out of order messages due to pre-emption. What
> kind of timing differences are we talking about? Are these microsecond
> level time deltas, or say tenths of a second?
> >>>> S
> >>>
> >>> We didn't want to run our file appender at high rates, because we
> assumed that would be bad from a file I/O standpoint. Running our stream
> appender faster would be fine.
> >>
> >> I don't think that it happens that way. If we have very high rate
> bursts, it just means that after finishing writing a number of events to
> disk, the appender comes back quickly to check for more work to do. Without
> that, we found that we had trouble keeping up with bursts.
> >>
> >>> The timing differences are very close to each other. Take this
> (pretend) example:
> >>>
> >>> /*
> >>> log("before");
> >>> doMethod();
> >>> log("after");
> >>>
> >>> def doMethod()
> >>> {
> >>> log("inside1");
> >>> log("inside2");
> >>> }
> >>> */
> >>
> >> That's Lua, right?
> >
> > Actually, it's just terrible psuedo-code. Apologies for not being clear.
> >
> >>
> >>> We could potentially get something like this in the logs:
> >>> /*
> >>> inside1
> >>> before
> >>> inside2
> >>> after
> >>> */
> >>>
> >>> My coworker just mentioned that he's even seen instances where
> "inside2" would come before "inside1" in the above (pretend) example.
> >>>
> >>> Weird stuff…
> >>
> >> Yeah, that's an understatement. I've never seen that within one
> component. Something is wrong ... Can you reproduce this with C++ logging
> calls?
> >>
> >> Do you get _all_ logging events in both appenders? Do you have both the
> file and the ostream appender attached to the same category? If so, how did
> you modify OCL to support that (trunk currently doesn't)?
> >> S
> >>
> >
> > This is all occurring using C++ components with a Lua deployment.
> >
> > I guess I don't understand your question about multiple appenders
> connected to the same category. With our current set up, when we write a
> log message, it goes to both stdout and the our log file. They're
> formatted differently (based on the appender's configuration), but I
> believe all our log messages go to both destinations. We made no
> modifications to OCL to support this behavior. We're running the 2.6 debs.
> >
> > Below is the relevant section of Lua deploy code, the CPF files used,
> and some snippets of C++ code that define the OCL::Logging categories.
> >
> > -dustin
>
> Nothing stands out in the code snippets you sent. All looks pretty
> vanilla, which is good.
>
> My question re multiple appenders is that the OCL::Logging implementation
> that I initially built only supported _one_ appender per category (there's
> only one output buffer port in each OCL::Category). So I'm curious _how_
> you got two appenders to successfully connect to the same category, as I
> don't recall anything on the ML about someone improving this
> implementation. Having said that, the version we are using is v1.10 based,
> so we are _way_ behind.
>

We fixed this in 2.x. There's one output port per category, and any number
of appenders can connect to it, and get their own buffer, with their own
copies of the log messages.

>
> I can't even theorize how events from the same component, logging to the
> same category, end up out of order. Does this still occur if you only log
> to one appender? The chain of events is straight forward
>
> 1. component logs to category
> 2. category hierarchy is traversed, when one is found that should log, it
> pushes the event onto the RTT::BufferPort of that category
> at some point later, an appender wakes up, finds a non-empty buffer, pops
> the contents, and then does whatever it needs to (e.ge. 3. write to file,
> write to console).
>
> There aren't many places to break that. 1 and 2 occur in the logging
> component's thread, and so they can't be interrupted by the component
> itself. 3 occurs later, but it pops events in order. This really isn't that
> complicated, unless something significantly changed this in a port to v2?
>

Don't know by heart, but out-of-order beats me too. It's message drops that
can occur...for the record -> this is within one category, right ?!

Peter