Hi,
I observed strange timestamps in my logging output and thus created a
simple example program:
#include <ros/ros.h>
int main(int argc, char **argv)
{
ros::init(argc, argv, "test_node");
ros::NodeHandle ros_node_handle;
ROS_INFO("Hello World");
return 0;
}
Since the timestamps looked like printing uninitialised memory, I ran
valgrind and indeed there were some problems. Valgrind's output is
attached.
To investigate the problem, I took the source of rosconsole from
https://github.com/ros/rosconsole (as well as roscpp), compiled it and
linked against it. The problem was gone, so I think this issue is
caused by wrong linkage to log4cxx in Testing.
Cheers,
Dino
==31551== Memcheck, a memory error detector
==31551== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==31551== Using Valgrind-3.13.0 and LibVEX; rerun with -h for copyright info
==31551== Command: ./devel/lib/my_package/my_node
==31551==
==31551== Use of uninitialised value of size 8
==31551== at 0x5DA333E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DA3D25: std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<unsigned long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long) const (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DAF3B4: std::ostream& std::ostream::_M_insert<unsigned long>(unsigned long) (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5611F4A: ros::operator<<(std::ostream&, ros::WallTime const&) (in /usr/lib/x86_64-linux-gnu/librostime.so.0.6.11)
==31551== by 0x4AAE308: ros::console::TimeToken::getString[abi:cxx11](void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACAFC: ros::console::Formatter::print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACDAF: ros::console::_print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4CD49CA: ros::console::impl::ROSConsoleStdioAppender::append(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/librosconsole_log4cxx.so.1.13.7)
==31551== by 0x51CBA18: log4cxx::AppenderSkeleton::doAppend(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x51C9C33: log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207D5C: log4cxx::Logger::callAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207F8D: log4cxx::Logger::forcedLog(log4cxx::helpers::ObjectPtrT<log4cxx::Level> const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, log4cxx::spi::LocationInfo const&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551==
==31551== Conditional jump or move depends on uninitialised value(s)
==31551== at 0x5DA334B: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DA3D25: std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<unsigned long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long) const (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DAF3B4: std::ostream& std::ostream::_M_insert<unsigned long>(unsigned long) (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5611F4A: ros::operator<<(std::ostream&, ros::WallTime const&) (in /usr/lib/x86_64-linux-gnu/librostime.so.0.6.11)
==31551== by 0x4AAE308: ros::console::TimeToken::getString[abi:cxx11](void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACAFC: ros::console::Formatter::print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACDAF: ros::console::_print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4CD49CA: ros::console::impl::ROSConsoleStdioAppender::append(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/librosconsole_log4cxx.so.1.13.7)
==31551== by 0x51CBA18: log4cxx::AppenderSkeleton::doAppend(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x51C9C33: log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207D5C: log4cxx::Logger::callAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207F8D: log4cxx::Logger::forcedLog(log4cxx::helpers::ObjectPtrT<log4cxx::Level> const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, log4cxx::spi::LocationInfo const&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551==
==31551== Use of uninitialised value of size 8
==31551== at 0x5DA333E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DA3D25: std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<unsigned long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long) const (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DAF3B4: std::ostream& std::ostream::_M_insert<unsigned long>(unsigned long) (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5611F9B: ros::operator<<(std::ostream&, ros::WallTime const&) (in /usr/lib/x86_64-linux-gnu/librostime.so.0.6.11)
==31551== by 0x4AAE308: ros::console::TimeToken::getString[abi:cxx11](void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACAFC: ros::console::Formatter::print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACDAF: ros::console::_print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4CD49CA: ros::console::impl::ROSConsoleStdioAppender::append(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/librosconsole_log4cxx.so.1.13.7)
==31551== by 0x51CBA18: log4cxx::AppenderSkeleton::doAppend(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x51C9C33: log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207D5C: log4cxx::Logger::callAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207F8D: log4cxx::Logger::forcedLog(log4cxx::helpers::ObjectPtrT<log4cxx::Level> const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, log4cxx::spi::LocationInfo const&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551==
==31551== Conditional jump or move depends on uninitialised value(s)
==31551== at 0x5DA334B: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DA3D25: std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<unsigned long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long) const (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5DAF3B4: std::ostream& std::ostream::_M_insert<unsigned long>(unsigned long) (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==31551== by 0x5611F9B: ros::operator<<(std::ostream&, ros::WallTime const&) (in /usr/lib/x86_64-linux-gnu/librostime.so.0.6.11)
==31551== by 0x4AAE308: ros::console::TimeToken::getString[abi:cxx11](void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACAFC: ros::console::Formatter::print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4AACDAF: ros::console::_print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x4CD49CA: ros::console::impl::ROSConsoleStdioAppender::append(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/librosconsole_log4cxx.so.1.13.7)
==31551== by 0x51CBA18: log4cxx::AppenderSkeleton::doAppend(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x51C9C33: log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207D5C: log4cxx::Logger::callAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207F8D: log4cxx::Logger::forcedLog(log4cxx::helpers::ObjectPtrT<log4cxx::Level> const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, log4cxx::spi::LocationInfo const&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551==
==31551== Conditional jump or move depends on uninitialised value(s)
==31551== at 0x49C90BF: ros::ROSOutAppender::log(ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/libroscpp.so.1.14.2)
==31551== by 0x4CD4E60: ros::console::impl::Log4cxxAppender::append(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/librosconsole_log4cxx.so.1.13.7)
==31551== by 0x51CBA18: log4cxx::AppenderSkeleton::doAppend(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x51C9C33: log4cxx::helpers::AppenderAttachableImpl::appendLoopOnAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207D5C: log4cxx::Logger::callAppenders(log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggingEvent> const&, log4cxx::helpers::Pool&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x5207F8D: log4cxx::Logger::forcedLog(log4cxx::helpers::ObjectPtrT<log4cxx::Level> const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, log4cxx::spi::LocationInfo const&) const (in /usr/lib/x86_64-linux-gnu/liblog4cxx.so.10.0.0)
==31551== by 0x4CD19FA: ros::console::impl::print(void*, ros::console::levels::Level, char const*, char const*, char const*, int) (in /usr/lib/x86_64-linux-gnu/librosconsole_log4cxx.so.1.13.7)
==31551== by 0x4AAB45B: ros::console::print(ros::console::FilterBase*, void*, ros::console::levels::Level, char const*, int, char const*, char const*, ...) (in /usr/lib/x86_64-linux-gnu/librosconsole.so.1.13.7)
==31551== by 0x10E4DA: main (main.cpp:15)
==31551==
==31551==
==31551== HEAP SUMMARY:
==31551== in use at exit: 4,216 bytes in 46 blocks
==31551== total heap usage: 1,292 allocs, 1,246 frees, 225,561 bytes allocated
==31551==
==31551== LEAK SUMMARY:
==31551== definitely lost: 0 bytes in 0 blocks
==31551== indirectly lost: 0 bytes in 0 blocks
==31551== possibly lost: 304 bytes in 1 blocks
==31551== still reachable: 3,912 bytes in 45 blocks
==31551== suppressed: 0 bytes in 0 blocks
==31551== Rerun with --leak-check=full to see details of leaked memory
==31551==
==31551== For counts of detected and suppressed errors, rerun with: -v
==31551== Use --track-origins=yes to see where uninitialised values come from
==31551== ERROR SUMMARY: 19 errors from 5 contexts (suppressed: 0 from 0)
