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"?>
> &lt;!DOCTYPE properties SYSTEM "cpf.dtd"&gt;
> <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"?>
> &lt;!DOCTYPE properties SYSTEM "cpf.dtd"&gt;
> <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"?>
> &lt;!DOCTYPE properties SYSTEM "cpf.dtd"&gt;
> <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;
> }
>
>
> **/