crashes and logger

Hi,

I've had different crashes, pointing to a line where something is
logged: (toolchain-2.2)
Is this my fault?
EXAMPLE 1 (other example below)
eg. where LaserMotion.cpp:
line 184: log(Debug) << "not initialized yet" << endlog();
line 185: log(Debug) << "T_o1_o2" << T_o1_o2 << endlog(); (T_o1_o2 is a
KDL::Frame, that was printed multiple times already before the crash)
He crashes sometimes on l184, sometimes l185, or somewhere else with a
log statement.
log4cpp is compiled...

20.256 [ Debug ][LaserMotion] not initialized yet
20.256 [ Debug ][LaserMotion] T_o1_o2[[ 1,
0, 0;
0, 1, 0;
0, 0, 1]
[ 0, 0, 0]]
20.266 [ Debug ][LaserMotion] not initialized yet
20.266 [ Debug ][LaserMotion] T_o1_o2[[ 1,
0, 0;
0, 1, 0;
0, 0, 1]
[ 0, 0, 0]]

*** glibc detected ***
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/ocl/bin/deployer-gnulinux:
corrupted double-linked list: 0xb56db540 ***
======= Backtrace: =========
/lib/libc.so.6(+0x6c501)[0xb78a3501]
/lib/libc.so.6(+0x6c93e)[0xb78a393e]
/lib/libc.so.6(+0x6dced)[0xb78a4ced]
/lib/libc.so.6(cfree+0x6d)[0xb78a7e5d]
/usr/lib/libstdc++.so.6(_ZdlPv+0x21)[0xb7a82441]
/usr/lib/libstdc++.so.6(_ZNSs4_Rep10_M_destroyERKSaIcE+0x1d)[0xb7a64acd]
/usr/lib/libstdc++.so.6(_ZNSt15basic_stringbufIcSt11char_traitsIcESaIcEE8overflowEi+0x16f)[0xb7a5e30f]
/usr/lib/libstdc++.so.6(_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKci+0x3d)[0xb7a6280d]
/usr/lib/libstdc++.so.6(_ZSt16__ostream_insertIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_PKS3_i+0x1ba)[0xb7a5852a]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT6Logger1D5logitEPFRSoS2_E+0x738)[0xb7edc408]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT6Logger7logendlEv+0x3b)[0xb7ed989b]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT6LoggerlsEPFRSoS1_E+0x128)[0xb7ed9a48]
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblasermotion-gnulinux.so(_ZN5iTaSC11LaserMotion10updateHookEv+0x1552)[0xb1a577d2]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT15ExecutionEngine15processChildrenEv+0xde)[0xb7e7c45e]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT15ExecutionEngine4stepEv+0x32)[0xb7e7cd72]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT8Activity4stepEv+0x18)[0xb7ecdfc8]
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/install/lib/liborocos-rtt-gnulinux.so.2.2(_ZN3RTT2os15thread_functionEPv+0x1d3)[0xb7ee75d3]
/lib/libpthread.so.0(+0x5cc9)[0xb7ad5cc9]
/lib/libc.so.6(clone+0x5e)[0xb79076ae]
======= Memory map: ========
08048000-08061000 r-xp 00000000 08:07 4587734
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/ocl/bin/deployer-gnulinux
08061000-08062000 r--p 00018000 08:07 4587734
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/ocl/bin/deployer-gnulinux
08062000-08063000 rw-p 00019000 08:07 4587734
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/ocl/bin/deployer-gnulinux
08063000-080a5000 rw-p 00000000 00:00 0 [heap]
a9146000-a9147000 ---p 00000000 00:00 0
a9147000-a9947000 rw-p 00000000 00:00 0
a9947000-a9948000 ---p 00000000 00:00 0
a9948000-aa148000 rw-p 00000000 00:00 0
aa148000-aa149000 ---p 00000000 00:00 0
aa149000-aa949000 rw-p 00000000 00:00 0
aa949000-aa94a000 ---p 00000000 00:00 0
aa94a000-ab14a000 rw-p 00000000 00:00 0
ab14a000-ab14b000 ---p 00000000 00:00 0
ab14b000-ab94b000 rw-p 00000000 00:00 0
ab94b000-ab94c000 ---p 00000000 00:00 0
ab94c000-ac14c000 rw-p 00000000 00:00 0
ac14c000-ac14d000 ---p 00000000 00:00 0
ac14d000-ac94d000 rw-p 00000000 00:00 0
ac94d000-ac94e000 ---p 00000000 00:00 0
ac94e000-ad14e000 rw-p 00000000 00:00 0
ad14e000-ad14f000 ---p 00000000 00:00 0
ad14f000-ad94f000 rw-p 00000000 00:00 0
ad94f000-ad950000 ---p 00000000 00:00 0
ad950000-ae150000 rw-p 00000000 00:00 0
ae951000-ae952000 ---p 00000000 00:00 0
ae952000-af152000 rw-p 00000000 00:00 0
af953000-af954000 ---p 00000000 00:00 0
af954000-b0154000 rw-p 00000000 00:00 0
b0955000-b0956000 ---p 00000000 00:00 0
b0956000-b1156000 rw-p 00000000 00:00 0
b170f000-b174f000 rw-p 00000000 00:00 0
b174f000-b1756000 r--s 00000000 08:05 251695
/usr/lib/gconv/gconv-modules.cache
b1756000-b1757000 r--p 002a1000 08:05 139259
/usr/lib/locale/locale-archive
b1757000-b1957000 r--p 00000000 08:05 139259
/usr/lib/locale/locale-archive
b1957000-b1b5c000 r-xp 00000000 08:07 3674937
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblasermotion-gnulinux.so
b1b5c000-b1b6d000 r--p 00204000 08:07 3674937
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblasermotion-gnulinux.so
b1b6d000-b1b6e000 rw-p 00215000 08:07 3674937
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblasermotion-gnulinux.so
b1b6e000-b1bed000 r-xp 00000000 08:07 3674939
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblissajousgenerator-gnulinux.so
b1bed000-b1bee000 ---p 0007f000 08:07 3674939
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblissajousgenerator-gnulinux.so
b1bee000-b1bf2000 r--p 0007f000 08:07 3674939
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblissajousgenerator-gnulinux.so
b1bf2000-b1bf3000 rw-p 00083000 08:07 3674939
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/liblissajousgenerator-gnulinux.so
b1bf3000-b1c65000 r-xp 00000000 08:07 3674941
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/libnaxesvelocitycontroller-gnulinux.so
b1c65000-b1c69000 r--p 00072000 08:07 3674941
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/libnaxesvelocitycontroller-gnulinux.so
b1c69000-b1c6a000 rw-p 00076000 08:07 3674941
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/libnaxesvelocitycontroller-gnulinux.so
b1c6a000-b1cbc000 r-xp 00000000 08:07 3674938
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/libdummyKukaLWR-gnulinux.so
b1cbc000-b1cbf000 r--p 00051000 08:07 3674938
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/libdummyKukaLWR-gnulinux.so
b1cbf000-b1cc0000 rw-p 00054000 08:07 3674938
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/lib/orocos/libdummyKukaLWR-gnulinux.so
b1cc0000-b241e000 r-xp 00000000 08:07 3544037
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/stacks/orocos_kinematics_dynamics/kdl_typekit/lib/orocos/types/libkdl_typekit-gnulinux.so
b241e000-b2456000 r--p 0075d000 08:07 3544037
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/stacks/orocos_kinematics_dynamics/kdl_typekit/lib/orocos/types/libkdl_typekit-gnulinux.so
b2456000-b2459000 rw-p 00795000 08:07 3544037
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/stacks/orocos_kinematics_dynamics/kdl_typekit/lib/orocos/types/libkdl_typekit-gnulinux.so
b2459000-b245a000 rw-p 00000000 00:00 0
b245a000-b2532000 r-xp 00000000 08:07 3543908
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/types/libeigen_toolkit-gnulinux.so
b2532000-b2533000 ---p 000d8000 08:07 3543908
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/types/libeigen_toolkit-gnulinux.so
b2533000-b2539000 r--p 000d8000 08:07 3543908
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/types/libeigen_toolkit-gnulinux.so
b2539000-b253a000 rw-p 000de000 08:07 3543908
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/types/libeigen_toolkit-gnulinux.so
b253a000-b26e4000 r-xp 00000000 08:07 3544063
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/libiTaSC_SingleJoint-gnulinux.so
b26e4000-b26e5000 ---p 001aa000 08:07 3544063
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/libiTaSC_SingleJoint-gnulinux.so
b26e5000-b26f3000 r--p 001aa000 08:07 3544063
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/libiTaSC_SingleJoint-gnulinux.so
b26f3000-b26f4000 rw-p 001b8000 08:07 3544063
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/iTaSC/lib/orocos/libiTaSC_SingleJoint-gnulinux.so
Program received signal SIGABRT, Aborted.
[Switching to Thread 0xad14db70 (LWP 12755)]
0xb7fe1424 in __kernel_vsyscall ()
(gdb) bt
#0 0xb7fe1424 in __kernel_vsyscall ()
#1 0xb7861941 in raise (sig=6) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#2 0xb7864e42 in abort () at abort.c:92
#3 0xb7899305 in __libc_message (do_abort=2, fmt=0xb79712c0 "*** glibc
detected *** %s: %s: 0x%s ***\n") at
../sysdeps/unix/sysv/linux/libc_fatal.c:189
#4 0xb78a3501 in malloc_printerr (action=<value optimized out>, str=0x6
<Address 0x6 out of bounds>, ptr=0xb56db540) at malloc.c:6283
#5 0xb78a393e in malloc_consolidate (av=<value optimized out>) at
malloc.c:5161
#6 0xb78a4ced in _int_free (av=<value optimized out>, p=0xb568c1d0) at
malloc.c:5034
#7 0xb78a7e5d in __libc_free (mem=0xb568c1d8) at malloc.c:3738
#8 0xb7a82441 in operator delete(void*) () from /usr/lib/libstdc++.so.6
#9 0xb7a64acd in std::basic_string<char, std::char_traits std::allocator<char> >::_Rep::_M_destroy(std::allocator<char> const&) ()
from /usr/lib/libstdc++.so.6
#10 0xb7a5e30f in std::basic_stringbuf<char, std::char_traits std::allocator<char> >::overflow(int) () from /usr/lib/libstdc++.so.6
#11 0xb7a6280d in std::basic_streambuf<char, std::char_traits >::xsputn(char const*, int) () from /usr/lib/libstdc++.so.6
#12 0xb7a5852a in std::basic_ostream<char, std::char_traits std::__ostream_insert<char, std::char_traits >(std::basic_ostream<char, std::char_traits () from /usr/lib/libstdc++.so.6
#13 0xb7edc408 in operator<< <char, std::char_traits std::allocator<char> > (this=0x8066778, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>)
at /usr/include/c++/4.4/bits/basic_string.h:2503
#14 RTT::Logger::D::logit (this=0x8066778, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>)
at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Logger.cpp:178
#15 0xb7ed989b in RTT::Logger::logendl (this=0x8066768) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Logger.cpp:564
#16 0xb7ed9a48 in RTT::Logger::operator<< (this=0x8066768, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>)
at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Logger.cpp:514
#17 0xb1a577d2 in iTaSC::LaserMotion::updateHook (this=0xb56112b0)
at
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/src/LaserMotion.cpp:185
#18 0xb7e7c45e in RTT::ExecutionEngine::processChildren (this=0xb5611170)
at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/ExecutionEngine.cpp:331
#19 0xb7e7cd72 in RTT::ExecutionEngine::step (this=0xb5611170) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/ExecutionEngine.cpp:321
#20 0xb7ecdfc8 in RTT::Activity::step (this=0xb5661820) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Activity.cpp:92
#21 0xb7ee75d3 in RTT::os::thread_function (t=0xb5661828) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/os/Thread.cpp:135
#22 0xb7ad5cc9 in start_thread (arg=0xad14db70) at pthread_create.c:304
#23 0xb79076ae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

EXAMPLE 2:

LaserMotion started
95.322 [ Debug ][LaserMotion] not initialized yet
95.322 [ Debug ][LaserMotion] T_o1_o2[[ 1,
0, 0;
0, 1, 0;
0, 0, 1]
[ 0, 0, 0]]

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xad0fab70 (LWP 12404)]
0xb78a4ba4 in _int_free (av=<value optimized out>, p=0x8162790) at
malloc.c:4973
4973 malloc.c: No such file or directory.
in malloc.c
(gdb) bt
#0 0xb78a4ba4 in _int_free (av=<value optimized out>, p=0x8162790) at
malloc.c:4973
#1 0xb78a7e5d in __libc_free (mem=0x8162798) at malloc.c:3738
#2 0xb7a82441 in operator delete(void*) () from /usr/lib/libstdc++.so.6
#3 0xb7a64acd in std::basic_string<char, std::char_traits std::allocator<char> >::_Rep::_M_destroy(std::allocator<char> const&) ()
from /usr/lib/libstdc++.so.6
#4 0xb7edc6be in _M_dispose (this=0x8066778, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>) at
/usr/include/c++/4.4/bits/basic_string.h:236
#5 ~basic_string (this=0x8066778, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>) at
/usr/include/c++/4.4/bits/basic_string.h:503
#6 RTT::Logger::D::logit (this=0x8066778, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>)
at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Logger.cpp:152
#7 0xb7ed989b in RTT::Logger::logendl (this=0x8066768) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Logger.cpp:564
#8 0xb7ed9a48 in RTT::Logger::operator<< (this=0x8066768, pf=0x8052128
<_ZN3RTT6Logger4endlERSo@plt>)
at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Logger.cpp:514
#9 0xb1b5a746 in iTaSC::LaserMotion::updateHook (this=0x80f88a0) at
/home/u0065688/src/svn/robotics-ros/packages/private-kul-ros-pkg/lissajous_lwr/src/LaserMotion.cpp:184
#10 0xb7e7c45e in RTT::ExecutionEngine::processChildren (this=0x80f8758)
at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/ExecutionEngine.cpp:331
#11 0xb7e7cd72 in RTT::ExecutionEngine::step (this=0x80f8758) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/ExecutionEngine.cpp:321
#12 0xb7ecdfc8 in RTT::Activity::step (this=0x81019d0) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/Activity.cpp:92
#13 0xb7ee75d3 in RTT::os::thread_function (t=0x81019d8) at
/home/u0065688/src/svn/robotics-ros/packages/orocos_toolchain_ros/rtt/rtt/os/Thread.cpp:135
#14 0xb7ad5cc9 in start_thread (arg=0xad0fab70) at pthread_create.c:304
#15 0xb79076ae in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130
(gdb) q

crashes and logger

On Wednesday 26 January 2011 17:05:31 Dominick Vanthienen wrote:
> Hi,
>
> I've had different crashes, pointing to a line where something is
> logged: (toolchain-2.2)
> Is this my fault?

I don't think so. Could you run the same with valgrind ?

We have a unit test that stresses the logger from different threads and which
doesn't crash. You could try to run that test on your system. The logger uses
Mutexes to protect against concurrent access. Maybe we don't cover all cases.

Peter

crashes and logger

with attachement 1

On 01/27/2011 12:14 PM, Peter Soetens wrote:
> On Wednesday 26 January 2011 17:05:31 Dominick Vanthienen wrote:
>> Hi,
>>
>> I've had different crashes, pointing to a line where something is
>> logged: (toolchain-2.2)
>> Is this my fault?
> I don't think so. Could you run the same with valgrind ?

Bizar thing is that when I change the statement from:
log(Debug)<< "T_o1_o2"<< T_o1_o2<< endlog();
to
log(Debug)<< "T_o1_o2"<< T_o1_o2<< " "<< endlog();
I don't have the problems anymore.

I can reproduce the same error with GDB by deleting this changes,
but valgrind says something else (see attachements)=> also other effect:
no data on port to LissajousGenerator (and thus not able to start),
thereby causing or not the updateHook of LaserMotion to be blocked
(I get this effect also sometimes when not using valgrind)

anyway, it seems to boil down to "eigen" problems
altough these files does take into account all the needed changes as
said before (alignment stuff)
> We have a unit test that stresses the logger from different threads and which
> doesn't crash. You could try to run that test on your system.
n the rtt/build/tests/ directory? which one?
> The logger uses
> Mutexes to protect against concurrent access. Maybe we don't cover all cases.
>
> Peter

crashes and logger

with attachment 2

On 01/27/2011 12:14 PM, Peter Soetens wrote:
> On Wednesday 26 January 2011 17:05:31 Dominick Vanthienen wrote:
>> Hi,
>>
>> I've had different crashes, pointing to a line where something is
>> logged: (toolchain-2.2)
>> Is this my fault?
> I don't think so. Could you run the same with valgrind ?

Bizar thing is that when I change the statement from:
log(Debug)<< "T_o1_o2"<< T_o1_o2<< endlog();
to
log(Debug)<< "T_o1_o2"<< T_o1_o2<< " "<< endlog();
I don't have the problems anymore.

I can reproduce the same error with GDB by deleting this changes,
but valgrind says something else (see attachements)=> also other effect:
no data on port to LissajousGenerator (and thus not able to start),
thereby causing or not the updateHook of LaserMotion to be blocked
(I get this effect also sometimes when not using valgrind)

anyway, it seems to boil down to "eigen" problems
altough these files does take into account all the needed changes as
said before (alignment stuff)
> We have a unit test that stresses the logger from different threads and which
> doesn't crash. You could try to run that test on your system.
n the rtt/build/tests/ directory? which one?
> The logger uses
> Mutexes to protect against concurrent access. Maybe we don't cover all cases.
>
> Peter