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

Submitted by snrkiwi on Fri, 2008-05-09 23:03

For more infomation about this bug, visit
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 [..] ...
ReportedBy: kiwi [dot] net [..] ...
CC: orocos-dev [..] ...
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
"
::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'
}}}

‹ [Bug 558] New: RTT does not compile for TAO 1.5.x [Bug 555] New: Ports AutoConnect feature fails ›
»

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

Submitted by sspr on Mon, 2008-05-26 20:40.

For more infomation about this bug, visit

--- Comment #11 from Peter Soetens
<peter [dot] soetens [..] ...> 2008-05-26 22:29:57 ---
Closing this again. But there is worse behaviour. We have seen unstability
(segfault) issues with the Logger when running under LXRT. That could be
related to this bug report. I've seen a long time a ago crashing loggers under
LXRT, which was caused by including an RTAI header file. The crashes are not
occuring under gnulinux. I've spotted a possible race (see patch below), but a
unit test could not confirm that it was a problem.

$ svn ci src/Logger.* -m"Fix outstanding issues of bug# 545: Logger In()
instances do not nest correctly"
Sending src/Logger.cpp
Sending src/Logger.inl
Transmitting file data ..
Committed revision 29320.
+ sspr@lt00129:~/src/Orocos/trunk/rtt
$ patch -p0 < logger-mutex.patch
patching file /home/sspr/src/Orocos/trunk/rtt/src/Logger.cpp
+ sspr@lt00129:~/src/Orocos/trunk/rtt
$ svn di src/Logger.cpp
Index: src/Logger.cpp
===================================================================
--- src/Logger.cpp (revision 29320)
+++ src/Logger.cpp (working copy)
@@ -272,7 +272,8 @@

std::string showModule() const
{
- return "["+std::string(moduleptr)+"]";
+ // moduleptr is protected by lock in logIt()
+ return "["+moduleptr+"]";
}

bool started;
@@ -367,7 +368,9 @@
}

std::string Logger::getLogModule() const {
- return d->moduleptr;
+ OS::MutexLock lock( d->inpguard );
+ std::string ret = d->moduleptr;
+ return ret;
}

+ sspr@lt00129:~/src/Orocos/trunk/rtt
$ svn ci src/Logger.* -m"Fix possible unprotected access for bug# 545: Logger
In() instances do not nest correctly"
Sending src/Logger.cpp
Transmitting file data .
Committed revision 29321.

»

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

Submitted by sspr on Mon, 2008-05-26 20:40.

For more infomation about this bug, visit

--- Comment #10 from Peter Soetens
<peter [dot] soetens [..] ...> 2008-05-26 22:25:05 ---
(In reply to comment #8)
> Furthermore: When logging is disabled
>
> /usr/bin/c++ -DRTT_DLL_EXPORT -g -fPIC -I/sw/include
> -I/Users/klaas/SVN/rtt-trunk/src -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src
> -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os
> -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os/gnulinux -Wall
> -DOROCOS_TARGET=gnulinux -o
> src/CMakeFiles/orocos-rtt-dynamic_gnulinux.dir/Logger.o -c
> /Users/klaas/SVN/rtt-trunk/src/Logger.cpp
> /Users/klaas/SVN/rtt-trunk/src/Logger.cpp:556: error: prototype for
> 'RTT::Logger::Logger()' does not match any in class 'RTT::Logger'
> /Users/klaas/SVN/rtt-trunk/src/Logger.hpp:92: error: candidates are:
> RTT::Logger::Logger(const RTT::Logger&)
> /Users/klaas/SVN/rtt-trunk/src/Logger.hpp:293: error:
> RTT::Logger::Logger(std::ostream&)

$ svn di Logger.cpp
Index: Logger.cpp
===================================================================
--- Logger.cpp (revision 29294)
+++ Logger.cpp (working copy)
@@ -553,7 +553,7 @@

#else // OROBLD_DISABLE_LOGGING

- Logger::Logger()
+ Logger::Logger(std::ostream& )
: d(0)
{
}

>
> And with remote logging enabled
>
> /usr/bin/c++ -DRTT_DLL_EXPORT -g -fPIC -I/sw/include
> -I/Users/klaas/SVN/rtt-trunk/src -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src
> -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os
> -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os/gnulinux -Wall
> -DOROCOS_TARGET=gnulinux -o
> src/CMakeFiles/orocos-rtt-dynamic_gnulinux.dir/Logger.o -c
> /Users/klaas/SVN/rtt-trunk/src/Logger.cpp
> /Users/klaas/SVN/rtt-trunk/src/Logger.cpp: In member function 'void
> RTT::Logger::D::logit(std::ostream& (*)(std::ostream&))':
>
> (seems like a problem with ORONUM_LOGGING_BUFSIZE non-existing? cmake issue?)
>

Yep. Can't reproduce this here... If you don't play with the LOGGING flags, you
won't have this problem :-)

Peter

»

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

Submitted by sspr on Mon, 2008-05-26 20:30.

For more infomation about this bug, visit

--- Comment #9 from Peter Soetens
<peter [dot] soetens [..] ...> 2008-05-26 22:21:50 ---
(In reply to comment #7)
> (In reply to comment #6)
> > $ svn ci -m"Fixes bug #545: Logger In() instances do not nest correctly.
> > Applied patch by S. Roderick (and P. Soetens)."
> > Sending rtt/src/Logger.cpp
> > Sending rtt/src/Logger.hpp
> > Sending rtt/src/Logger.inl
> > Transmitting file data ...
> > Committed revision 29292.
>
> Did you guys actually compile test this?
> http://svn.mech.kuleuven.be/websvn/orocos/trunk/rtt/src/Logger.inl?op=diff&rev=29292&sc=1
>
> I find it hard to believe that g++ on gnulinux would not detect this?
> /usr/bin/c++ -DRTT_DLL_EXPORT -g -fPIC -I/sw/include
> -I/Users/klaas/SVN/rtt-trunk/src -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src
> -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os
> -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os/gnulinux -Wall
> -DOROCOS_TARGET=gnulinux -o
> src/CMakeFiles/orocos-rtt-dynamic_gnulinux.dir/Attribute.o -c
> /Users/klaas/SVN/rtt-trunk/src/Attribute.cpp
> /Users/klaas/SVN/rtt-trunk/src/Logger.inl:106: error: redefinition of
> 'RTT::Logger& RTT::Logger::operator<<(const std::string&)'
> /Users/klaas/SVN/rtt-trunk/src/Logger.inl:102: error: 'RTT::Logger&
> RTT::Logger::operator<<(const std::string&)' previously defined here
>
Smells like a patch bug... the solution is easy:

$ svn di Logger.inl
Index: Logger.inl
===================================================================
--- Logger.inl (revision 29294)
+++ Logger.inl (working copy)
@@ -103,10 +103,6 @@
return *this;
}

- inline Logger& Logger::operator<<( const std::string& ) {
- return *this;
- }
-
inline Logger& Logger::operator<<(LogLevel) {
return *this;
}

»

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

Submitted by klaas on Mon, 2008-05-26 19:55.

For more infomation about this bug, visit

--- Comment #8 from Klaas Gadeyne <klaas [dot] gadeyne [..] ...> 2008-05-26 21:45:39 ---
Furthermore: When logging is disabled

/usr/bin/c++ -DRTT_DLL_EXPORT -g -fPIC -I/sw/include
-I/Users/klaas/SVN/rtt-trunk/src -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src
-I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os
-I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os/gnulinux -Wall
-DOROCOS_TARGET=gnulinux -o
src/CMakeFiles/orocos-rtt-dynamic_gnulinux.dir/Logger.o -c
/Users/klaas/SVN/rtt-trunk/src/Logger.cpp
/Users/klaas/SVN/rtt-trunk/src/Logger.cpp:556: error: prototype for
'RTT::Logger::Logger()' does not match any in class 'RTT::Logger'
/Users/klaas/SVN/rtt-trunk/src/Logger.hpp:92: error: candidates are:
RTT::Logger::Logger(const RTT::Logger&)
/Users/klaas/SVN/rtt-trunk/src/Logger.hpp:293: error:
RTT::Logger::Logger(std::ostream&)

And with remote logging enabled

/usr/bin/c++ -DRTT_DLL_EXPORT -g -fPIC -I/sw/include
-I/Users/klaas/SVN/rtt-trunk/src -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src
-I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os
-I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os/gnulinux -Wall
-DOROCOS_TARGET=gnulinux -o
src/CMakeFiles/orocos-rtt-dynamic_gnulinux.dir/Logger.o -c
/Users/klaas/SVN/rtt-trunk/src/Logger.cpp
/Users/klaas/SVN/rtt-trunk/src/Logger.cpp: In member function 'void
RTT::Logger::D::logit(std::ostream& (*)(std::ostream&))':

(seems like a problem with ORONUM_LOGGING_BUFSIZE non-existing? cmake issue?)

»

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

Submitted by klaas on Mon, 2008-05-26 19:45.

For more infomation about this bug, visit

Klaas Gadeyne <klaas [dot] gadeyne [..] ...> changed:

What |Removed |Added
--------------------------------------------------------------------------
Status|RESOLVED |REOPENED
Resolution|FIXED |
CC| |klaas [dot] gadeyne [..] ...

--- Comment #7 from Klaas Gadeyne <klaas [dot] gadeyne [..] ...> 2008-05-26 21:35:19 ---
(In reply to comment #6)
> $ svn ci -m"Fixes bug #545: Logger In() instances do not nest correctly.
> Applied patch by S. Roderick (and P. Soetens)."
> Sending rtt/src/Logger.cpp
> Sending rtt/src/Logger.hpp
> Sending rtt/src/Logger.inl
> Transmitting file data ...
> Committed revision 29292.

Did you guys actually compile test this?
http://svn.mech.kuleuven.be/websvn/orocos/trunk/rtt/src/Logger.inl?op=diff&rev=29292&sc=1

I find it hard to believe that g++ on gnulinux would not detect this?
/usr/bin/c++ -DRTT_DLL_EXPORT -g -fPIC -I/sw/include
-I/Users/klaas/SVN/rtt-trunk/src -I/Users/klaas/SVN/rtt-trunk/buildmacosx/src
-I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os
-I/Users/klaas/SVN/rtt-trunk/buildmacosx/src/os/gnulinux -Wall
-DOROCOS_TARGET=gnulinux -o
src/CMakeFiles/orocos-rtt-dynamic_gnulinux.dir/Attribute.o -c
/Users/klaas/SVN/rtt-trunk/src/Attribute.cpp
/Users/klaas/SVN/rtt-trunk/src/Logger.inl:106: error: redefinition of
'RTT::Logger& RTT::Logger::operator<<(const std::string&)'
/Users/klaas/SVN/rtt-trunk/src/Logger.inl:102: error: 'RTT::Logger&
RTT::Logger::operator<<(const std::string&)' previously defined here

»

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

Submitted by sspr on Fri, 2008-05-16 21:15.

For more infomation about this bug, visit

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

What |Removed |Added
--------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution| |FIXED
Target Milestone|--- |1.6.0

--- Comment #6 from Peter Soetens
<peter [dot] soetens [..] ...> 2008-05-16 23:06:27 ---
$ svn ci -m"Fixes bug #545: Logger In() instances do not nest correctly.
Applied patch by S. Roderick (and P. Soetens)."
Sending rtt/src/Logger.cpp
Sending rtt/src/Logger.hpp
Sending rtt/src/Logger.inl
Transmitting file data ...
Committed revision 29292.

Applied, thanks.

Peter

»

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

Submitted by sspr on Fri, 2008-05-16 08:30.

For more infomation about this bug, visit

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

What |Removed |Added
--------------------------------------------------------------------------
Attachment #281 is|0 |1
obsolete| |

--- Comment #5 from Peter Soetens
<peter [dot] soetens [..] ...> 2008-05-16 10:23:00 ---
Created an attachment (id=290)
--> (https://www.fmtc.be/bugzilla/orocos/attachment.cgi?id=290)
Slightly modified version of patch 281

This patch adds the mutex and further cleans up the Logger::D implementation
class.

»

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

Submitted by sspr on Sun, 2008-05-11 21:10.

For more infomation about this bug, visit

--- Comment #4 from Peter Soetens
<peter [dot] soetens [..] ...> 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.

»

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

Submitted by sspr on Sun, 2008-05-11 21:05.

For more infomation about this bug, visit

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

What |Removed |Added
--------------------------------------------------------------------------
CC| |peter [dot] soetens [..] ...

--- Comment #3 from Peter Soetens
<peter [dot] soetens [..] ...> 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

Submitted by snrkiwi on Fri, 2008-05-09 23:10.

For more infomation about this bug, visit

--- Comment #2 from S Roderick <kiwi [dot] net [..] ...> 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

Submitted by snrkiwi on Fri, 2008-05-09 23:10.

For more infomation about this bug, visit

--- Comment #1 from S Roderick <kiwi [dot] net [..] ...> 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

»