[log] Segfault in "rotating_file" example
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<boost::_bi::unspecified, boost::log::v2s_mt_posix::sinks::(anonymous namespace)::date_and_time_formatter, boost::_bi::list2<boost::_bi::bind_t<boost::_bi::unspecified, boost::log::v2s_mt_posix::sinks::(anonymous namespace)::file_counter_formatter, boost::_bi::list2<boost::_bi::value<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-tp4... Sent from the Boost - Dev mailing list archive at Nabble.com.
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?
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?
(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,
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> 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
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.
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
participants (3)
-
Andrey Semashev -
Jason -
Jason Roehm