[Bug 545] New: Logger In() instances do not nest correctly

For more infomation about this bug, visit <https://www.fmtc.be/bugzilla/orocos/show_bug.cgi?id=545>

           Summary: Logger In() instances do not nest correctly
           Product: RTT
           Version: rtt-trunk
          Platform: All
        OS/Version: All
            Status: NEW
          Severity: normal
          Priority: P2
         Component: Real-Time Toolkit (RTT)
        AssignedTo: orocos-dev at lists [dot] mech [dot] kuleuven [dot] be
        ReportedBy: kiwi.net at mac [dot] com
                CC: orocos-dev at lists [dot] mech [dot] kuleuven [dot] be
   Estimated Hours: 0.0

You can not nest Logger In() instances and have them correctly restore the
module name when they go out of scope.


   log( Debug )  << "Before outer"<< endlog();
        {
                Logger::In in("outer");
                log( Debug )  << "In outer"<< endlog();
                {
                        Logger::In in("inner");
                        log( Debug )  << "In inner"<< endlog();
                }
                log( Debug )  << "After inner"<< endlog();
        }
    log( Debug )  << "After outer"<< endlog();

produces


4.176 [[ Debug  ][[Logger] Before outer
4.176 [[ Debug  ][[outer] In outer
4.176 [[ Debug  ][[inner] In inner
4.176 [[ Debug  ][[Logger] After inner
4.176 [[ Debug  ][[Logger] After outer

The "After inner" line should be prefixed with "[outer]" no "[Logger]", as the
"Logger::In in("outer");" is still in scope. Output with the patch


3.852 [[ Debug  ][[./core-test::main()] Before outer
3.852 [[ Debug  ][[outer] In outer
3.852 [[ Debug  ][[inner] In inner
3.852 [[ Debug  ][[outer] After inner
3.852 [[ Debug  ][[./core-test::main()] After outer

Note that the patch appears to expose that default logger entries should have
"<program>::main()" as their prefix, not "Logger" (set in rtt/src/os/main.h).
Not sure if you want this behaviour returned or not?.

Attached test.patch adds to rtt/tests/logger_test.cpp to demonstrate failure.

Attached fix.patch is a proposed patch which fixes this problem.

This problem is demonstrated within the Deployment component. The following is
the logger output from Deployment::loadComponents() in which a
PropertyMarshaller instance created part way through the function causes later
logging within configureComponents() to appear to be from the "Logger" instead
of from "Deployment::loadComponents"


0.022 [[ Info   ][[Logger] No plugins present in
/usr/local/orocos/lib/rtt/gnulinux/plugins
0.022 [[ Info   ][[DeploymentComponent::loadComponents] Loading
'data/orocos/deploy-test.xml'.
0.086 [[ Info   ][[Logger] Validating new configuration...
0.146 [[ Info   ][[DeploymentComponent::loadLibrary] Loaded multi component
library '/opt/code/nrl/local/lib/liborocos-reporting-gnulinux.so'

and after the proposed patch


0.006 [[ Info   ][[deployer-gnulinux::main()] No plugins present in
/usr/local/orocos/lib/rtt/gnulinux/plugins
0.006 [[ Info   ][[DeploymentComponent::loadComponents] Loading
'data/orocos/deploy-test.xml'.
0.029 [[ Info   ][[DeploymentComponent::loadComponents] Validating new
configuration...
0.041 [[ Info   ][[DeploymentComponent::loadLibrary] Loaded multi component
library '/opt/code/nrl/local/lib/liborocos-reporting-gnulinux.so'


Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.

[Bug 545] Logger In() instances do not nest correctly

For more infomation about this bug, visit <https://www.fmtc.be/bugzilla/orocos/show_bug.cgi?id=545>

--- Comment #1 from S Roderick <kiwi.net at mac [dot] com>  2008-05-10 01:03:49 ---

Created an attachment (id=280)

 --> (https://www.fmtc.be/bugzilla/orocos/attachment.cgi?id=280)

Patch to test case


[Bug 545] Logger In() instances do not nest correctly

For more infomation about this bug, visit <https://www.fmtc.be/bugzilla/orocos/show_bug.cgi?id=545>

--- Comment #2 from S Roderick <kiwi.net at mac [dot] com>  2008-05-10 01:04:05 ---

Created an attachment (id=281)

 --> (https://www.fmtc.be/bugzilla/orocos/attachment.cgi?id=281)

Proposed patch


[Bug 545] Logger In() instances do not nest correctly

For more infomation about this bug, visit <https://www.fmtc.be/bugzilla/orocos/show_bug.cgi?id=545>

Peter Soetens <peter.soetens at fmtc [dot] be> changed:

           What    |Removed                     |Added
 --------------------------------------------------------------------------
                 CC|                            |peter.soetens@fmtc.be
--- Comment #3 from Peter Soetens <peter.soetens at fmtc [dot] be>  2008-05-11 22:54:08 ---

The Logger did this correctly before, but we had to disable this behaviour
because of multi-threaded issues, see bug #428. The resolution of that bug was
a quick and dirty 'fix'. You solved it more graciously by using std::string,
which makes a copy on the local stack. However, you should still be aware that
you may/will get false 'locations' each time two threads pre-empt the current
thread in a special way. Also, I'm unsure of the thread-safeness of the
mechanism. Is a

 std::string a = b;  // b from thread X.

thread-safe? According to STL standards it is not. We could use the 'lock' of
the Logger to protect the assignment though. That would fix it once and for
all.

Peter


[Bug 545] Logger In() instances do not nest correctly

For more infomation about this bug, visit <https://www.fmtc.be/bugzilla/orocos/show_bug.cgi?id=545>

--- Comment #4 from Peter Soetens <peter.soetens at fmtc [dot] be>  2008-05-11 22:59:55 ---

(In reply to comment #2)
> Created an attachment (id=281)

 --> (https://www.fmtc.be/bugzilla/orocos/attachment.cgi?id=281) [details]

> Proposed patch
>
We can also get rid of the loggermodule variable in Logger::D then.
Nice patch BTW. Especially the formatting :-D.