[boost] [log] Segfault in "rotating_file" example

[Jason]

I'm working from SVN trunk revision 83923. I've been experiencing segfaults
when trying to set up a file sink that has date/time format specifiers in
its file name. I thought I was doing something wrong, but I found that the
"rotating_file" example also illustrates the same behavior. Here is a sample
backtrace:

#0 0x000000000077c0b8 in ?? ()
#1 0x0000000000415d25 in
boost::date_time::microsec_clock<boost::posix_time::ptime>::create_time
(converter=0x77c0b8)
at /code/env/include/boost/date_time/microsec_time_clock.hpp:100
#2 0x00000000004d628b in boost::log::v2s_mt_posix::sinks::(anonymous
namespace)::date_and_time_formatter::operator()(std::string const&, unsigned
int) const [clone .isra.401]
()
#3 0x00000000004d639a in
boost::log::v2s_mt_posix::aux::light_function<std::string (unsigned
int)>::impl<boost::_bi::bind_t&lt;boost::_bi::unspecified,
boost::log::v2s_mt_posix::sinks::(anonymous
namespace)::date_and_time_formatter,
boost::_bi::list2&lt;boost::_bi::bind_t&lt;boost::_bi::unspecified,
boost::log::v2s_mt_posix::sinks::(anonymous
namespace)::file_counter_formatter,
boost::_bi::list2&lt;boost::_bi::value&lt;std::string>, boost::arg<1> > >,
boost::arg<1> > >
>::invoke_impl(boost::log::v2s_mt_posix::aux::light_function<std::string
(unsigned int)>::impl_base*, unsigned int) ()
#4 0x00000000004d3c90 in
boost::log::v2s_mt_posix::sinks::text_file_backend::consume(boost::log::v2s_mt_posix::record_view
const&, std::string const&) ()
#5 0x00000000004206c6 in
boost::log::v2s_mt_posix::sinks::basic_formatting_sink_frontend<char>::feed_record<boost::log::v2s_mt_posix::aux::fake_mutex,
boost::log::v2s_mt_posix::sinks::text_file_backend>
(this=this@entry=0x783600, rec=..., backend_mutex=..., backend=...)
at /code/env/include/boost/log/sinks/basic_sink_frontend.hpp:445
#6 0x000000000042082f in
boost::log::v2s_mt_posix::sinks::basic_formatting_sink_frontend<char>::try_feed_record<boost::mutex,
boost::log::v2s_mt_posix::sinks::text_file_backend> (this=0x783600, rec=...,
backend_mutex=..., backend=...) at
/code/env/include/boost/log/sinks/basic_sink_frontend.hpp:489
#7 0x00000000004c1475 in
boost::log::v2s_mt_posix::core::push_record_move(boost::log::v2s_mt_posix::record&)
()
#8 0x000000000040dff1 in push_record (this=<optimized out>, rec=...) at
/code/env/include/boost/log/core/core.hpp:308
#9 push_record_unlocked (rec=..., this=<optimized out>) at
/code/env/include/boost/log/sources/basic_logger.hpp:268
#10 push_record (rec=..., this=<optimized out>) at
/code/env/include/boost/log/sources/basic_logger.hpp:582
#11 ~record_pump (this=0x7fffffffddc0, __in_chrg=<optimized out>) at
/code/env/include/boost/log/sources/record_ostream.hpp:279
#12 main (argc=<optimized out>, argv=<optimized out>) at main.cpp:84

Looking at the disassembly of where the segfault happens, it seems to have
gone off the rails and is executing invalid code. Specifically, the function
pointer "converter" inside the date_time::microsec_clock<>:create_time()
function seems to be invalid. Any ideas? I'm using gcc 4.7.2 on Ubuntu
12.10.

Jason



--
View this message in context: http://boost.2283326.n4.nabble.com/log-Segfault-in-rotating-file-example-tp4645502.html
Sent from the Boost - Dev mailing list archive at Nabble.com.

_______________________________________________
Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost

[Andrey Semashev]

On Tuesday 16 April 2013 11:55:53 Jason wrote:
> I'm working from SVN trunk revision 83923. I've been experiencing segfaults
> when trying to set up a file sink that has date/time format specifiers in
> its file name. I thought I was doing something wrong, but I found that the
> "rotating_file" example also illustrates the same behavior. Here is a sample
> backtrace:
>

> Looking at the disassembly of where the segfault happens, it seems to have
> gone off the rails and is executing invalid code. Specifically, the function
> pointer "converter" inside the date_time::microsec_clock<>:create_time()
> function seems to be invalid. Any ideas? I'm using gcc 4.7.2 on Ubuntu
> 12.10.

I have the same setup and the rotating_file example runs fine for me (I tried
with revision 83930 though). What compiler switches do you use?

[Jason Roehm]

On 04/16/2013 03:11 PM, Andrey Semashev wrote:
> On Tuesday 16 April 2013 11:55:53 Jason wrote:
>> I'm working from SVN trunk revision 83923. I've been experiencing segfaults
>> when trying to set up a file sink that has date/time format specifiers in
>> its file name. I thought I was doing something wrong, but I found that the
>> "rotating_file" example also illustrates the same behavior. Here is a sample
>> backtrace:
>>
>> Looking at the disassembly of where the segfault happens, it seems to have
>> gone off the rails and is executing invalid code. Specifically, the function
>> pointer "converter" inside the date_time::microsec_clock<>:create_time()
>> function seems to be invalid. Any ideas? I'm using gcc 4.7.2 on Ubuntu
>> 12.10.
> I have the same setup and the rotating_file example runs fine for me (I tried
> with revision 83930 though). What compiler switches do you use?

I think I found the problem. I'm using posix_time's extended-precision
mode, where it provides resolution in nanoseconds instead of
microseconds (enabled by defining the preprocessor symbol
BOOST_DATE_TIME_POSIX_TIME_STD_CONFIG). I had this symbol defined in my
source code, but I did not define it when building Boost. I fixed that,
and now the example runs successfully. Also, my program also is able to
log messages.

With that said, I'm now experiencing a segfault at shutdown. It appears
down in the text_file_backend code:

#0 0x0000000f00000000 in ?? ()
#1 0x00007ffff358c9cd in __dynamic_cast () from
/usr/lib/x86_64-linux-gnu/libstdc++.so.6
#2 0x00007ffff35d14cb in std::codecvt<wchar_t, char, __mbstate_t>
const& std::use_facet<std::codecvt<wchar_t, char, __mbstate_t>
>(std::locale const&) ()
from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3 0x00007ffff753c3e5 in boost::filesystem::path::parent_path() const
() from
/home/jasonr/gbot2/cfg/../packages/env/lib/libboost_filesystem.so.1.54.0
#4 0x00007ffff72e03b6 in boost::log::v2_mt_posix::sinks::(anonymous
namespace)::file_collector::store_file(boost::filesystem::path const&) ()
from /home/jasonr/gbot2/cfg/../packages/env/lib/libboost_log.so.1.54.0
#5 0x00007ffff72df906 in
boost::log::v2_mt_posix::sinks::text_file_backend::~text_file_backend() ()
from /home/jasonr/gbot2/cfg/../packages/env/lib/libboost_log.so.1.54.0
#6 0x00000000004cb189 in destroy (this=0x98f598) at
/code/env/include/boost/smart_ptr/make_shared_object.hpp:57
#7 destroy (this=0x98f598) at
/code/env/include/boost/smart_ptr/detail/sp_counted_impl.hpp:151
#8 operator() (this=0x98f598) at
/code/env/include/boost/smart_ptr/make_shared_object.hpp:87
#9
boost::detail::sp_counted_impl_pd<boost::log::v2_mt_posix::sinks::text_file_backend*,
boost::detail::sp_ms_deleter<boost::log::v2_mt_posix::sinks::text_file_backend>
>::dispose (this=0x98f580) at
/code/env/include/boost/smart_ptr/detail/sp_counted_impl.hpp:153
#10 0x00000000004d337a in release (this=0x98f580) at
/code/env/include/boost/smart_ptr/detail/sp_counted_base_gcc_x86.hpp:146
#11 ~shared_count (this=0x98f2b8, __in_chrg=<optimized out>) at
/code/env/include/boost/smart_ptr/detail/shared_count.hpp:371
#12 ~shared_ptr (this=0x98f2b0, __in_chrg=<optimized out>) at
/code/env/include/boost/smart_ptr/shared_ptr.hpp:328
#13
boost::log::v2_mt_posix::sinks::asynchronous_sink<boost::log::v2_mt_posix::sinks::text_file_backend,
boost::log::v2_mt_posix::sinks::unbounded_fifo_queue>::~asynchronous_sink (this=0x98f1c0,

__in_chrg=<optimized out>) at

/code/env/include/boost/log/sinks/async_frontend.hpp:267
#14 0x00000000004d3429 in
boost::log::v2_mt_posix::sinks::asynchronous_sink<boost::log::v2_mt_posix::sinks::text_file_backend,
boost::log::v2_mt_posix::sinks::unbounded_fifo_queue>::~asynchronous_sink (this=0x98f1c0,

__in_chrg=<optimized out>) at

/code/env/include/boost/log/sinks/async_frontend.hpp:267
#15 0x00007ffff72bea70 in boost::log::v2_mt_posix::core::~core() () from
/home/jasonr/gbot2/cfg/../packages/env/lib/libboost_log.so.1.54.0
#16 0x00007ffff72c1e12 in
boost::detail::sp_counted_impl_p<boost::log::v2_mt_posix::core>::dispose()
()
from /home/jasonr/gbot2/cfg/../packages/env/lib/libboost_log.so.1.54.0
#17 0x00000000004cc509 in release (this=0x78fdc0) at
/code/env/include/boost/smart_ptr/detail/sp_counted_base_gcc_x86.hpp:146
#18 ~shared_count (this=<optimized out>, __in_chrg=<optimized out>) at
/code/env/include/boost/smart_ptr/detail/shared_count.hpp:371
#19 boost::shared_ptr<boost::log::v2_mt_posix::core>::~shared_ptr
(this=<optimized out>, __in_chrg=<optimized out>)
at /code/env/include/boost/smart_ptr/shared_ptr.hpp:328
#20 0x00007ffff2c98901 in __run_exit_handlers (status=0,
listp=0x7ffff30156a8 <__exit_funcs>, run_list_atexit=true) at exit.c:78
#21 0x00007ffff2c98985 in __GI_exit (status=<optimized out>) at exit.c:100
#22 0x00007ffff2c7e774 in __libc_start_main (main=0x42f630 <main(int,
char**)>, argc=1, ubp_av=0x7fffffffe148, init=<optimized out>,
fini=<optimized out>,
rtld_fini=<optimized out>, stack_end=0x7fffffffe138) at
libc-start.c:258
#23 0x0000000000431481 in _start ()

However, I don't see this problem with any examples that I've tried, so
it's not clear to me where the problem is. The crash is down in
boost::filesystem. I'm not sure whether it's trying to access some
resource too late in the shutdown process or what.

On a side note, I wanted to point out that Boost.Log looks fantastic. It
may seem a bit complex at first, but the amount of flexibility and
extensibility is well beyond any other logging facility I've seen before.

Jason

[Andrey Semashev]

On Tuesday 16 April 2013 16:03:56 Jason Roehm wrote:
>
> With that said, I'm now experiencing a segfault at shutdown. It appears
> down in the text_file_backend code:
>

> However, I don't see this problem with any examples that I've tried, so
> it's not clear to me where the problem is. The crash is down in
> boost::filesystem. I'm not sure whether it's trying to access some
> resource too late in the shutdown process or what.

Well, from the backtrace it seems like the library tries to perform the last
file rotation and calls filesystem::path::parent_path at some point, which
tries to construct a path and access a locale facet for character code
conversion. The problem is that the locale is stored as a function-local
static in Boost.Filesystem and is destroyed at this point.

I think this should be reported to Boost.Filesystem maintainer as this
limitation with a global locale is quite unexpected from a user's standpoint.
I think there is also a thread safety issue related to it that I reported
quite some time ago, and it is still not fixed.

As for Boost.Log, I'm not sure I can work it around in my code, except to
avoid using Boost.Filesystem, which would be unfortunate. You can try to work
around it on yor side though. If you access filesystem::path in the way so
that the locale gets initialized _before_ you make any use of Boost.Log, then
the locale should still be valid when Boost.Log is deinitialized.

> On a side note, I wanted to point out that Boost.Log looks fantastic. It
> may seem a bit complex at first, but the amount of flexibility and
> extensibility is well beyond any other logging facility I've seen before.

Thank you for the kind words.

[Jason Roehm]

On 04/16/2013 04:38 PM, Andrey Semashev wrote:
> Well, from the backtrace it seems like the library tries to perform the last
> file rotation and calls filesystem::path::parent_path at some point, which
> tries to construct a path and access a locale facet for character code
> conversion. The problem is that the locale is stored as a function-local
> static in Boost.Filesystem and is destroyed at this point.
>
> I think this should be reported to Boost.Filesystem maintainer as this
> limitation with a global locale is quite unexpected from a user's standpoint.
> I think there is also a thread safety issue related to it that I reported
> quite some time ago, and it is still not fixed.
>
> As for Boost.Log, I'm not sure I can work it around in my code, except to
> avoid using Boost.Filesystem, which would be unfortunate. You can try to work
> around it on yor side though. If you access filesystem::path in the way so
> that the locale gets initialized _before_ you make any use of Boost.Log, then
> the locale should still be valid when Boost.Log is deinitialized.
>

Thanks for the recommendation. I wasn't able to figure out how to access
filesystem::path appropriately in order to keep the locale alive, but I
did create a workaround. Just before application shutdown, I call a
function that explicitly removes the sinks from the logging core, which
then causes them to be destroyed. The application then shuts down
successfully without any problems.

Jason