Actions
Bug #2343
closedSIGABRT in osmo-trx
Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
UHD
Target version:
-
Start date:
06/29/2017
Due date:
% Done:
100%
Spec Reference:
Description
It's pretty hard to reproduce but happens from time to time:
NOTICE 140737352087296 12:20:15.0 Transceiver.cpp:381:pushRadioVector: dumping STALE burst in TRX->USRP interface
NOTICE 140737352087296 12:20:15.0 Transceiver.cpp:381:pushRadioVector: dumping STALE burst in TRX->USRP interface
NOTICE 140737352087296 12:20:15.0 Transceiver.cpp:381:pushRadioVector: dumping STALE burst in TRX->USRP interface
NOTICE 140737352386304 12:20:15.5 Transceiver.cpp:297:stop: Stopping the transceiver
terminate called without an active exception
[Thread 0x7ffff7e0b700 (LWP 20525) exited]
Thread 24 "osmo-trx" received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff0e96700 (LWP 20526)]
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
58 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
#1 0x00007ffff5f4b37a in __GI_abort () at abort.c:89
#2 0x00007ffff688c56d in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3 0x00007ffff688a316 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4 0x00007ffff688a361 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#5 0x00007ffff6889f5c in __gxx_personality_v0 () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#6 0x00007ffff62eb019 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#7 0x00007ffff62eb45d in _Unwind_Resume () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#8 0x00007ffff690e114 in std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#9 0x000055555558f655 in std::operator<< <char, std::char_traits<char>, std::allocator<char> > (
__str="ERR 140737235216128 12:20:16.3 UHDDevice.cpp:843:check_rx_md_err: No packet received, implementation timed-out", __os=...)
at /usr/include/c++/6/bits/basic_string.h:5345
#10 Log::~Log (this=0x7ffff0e94d40, __in_chrg=<optimized out>) at Logger.cpp:228
#11 0x0000555555576d7c in uhd_device::check_rx_md_err (this=this@entry=0x5555557e4190, md=..., num_smpls=num_smpls@entry=0)
at UHDDevice.cpp:843
#12 0x000055555557e1e2 in uhd_device::readSamples (this=0x5555557e4190, bufs=std::vector of length 1, capacity 1 = {...}, len=625,
overrun=<optimized out>, timestamp=680913461, underrun=<optimized out>, RSSI=0x0) at UHDDevice.cpp:929
#13 0x0000555555560b00 in RadioInterface::pullBuffer (this=0x55555582a600) at radioInterface.cpp:313
#14 0x000055555555fd5e in RadioInterface::driveReceiveRadio (this=0x55555582a600) at radioInterface.cpp:229
#15 0x0000555555565410 in Transceiver::driveReceiveRadio (this=this@entry=0x555555845f40) at Transceiver.cpp:874
#16 0x00005555555654c8 in RxLowerLoopAdapter (transceiver=0x555555845f40) at Transceiver.cpp:1033
#17 0x00007ffff7bc06da in start_thread (arg=0x7ffff0e96700) at pthread_create.c:456
#18 0x00007ffff601cd7f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105
The full trace:
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
set = {__val = {0, 140737354103816, 140737235206736, 8455341136, 140737354102960, 140737235206720, 140737329128731,
252833149, 4294967295, 140737235207184, 140737319644632, 140737353923024, 140737235206816, 8427343944, 140737354102960,
140737235206800}}
pid = <optimized out>
tid = <optimized out>
#1 0x00007ffff5f4b37a in __GI_abort () at abort.c:89
save_stage = 2
act = {__sigaction_handler = {sa_handler = 0x6b636568633a3334, sa_sigaction = 0x6b636568633a3334}, sa_mask = {__val = {
7304667541534175839, 3432, 140737320120824, 45, 280375465082880, 2318338295130056035, 140737323558176, 45,
140737330244016, 45, 45, 45, 140737323562832, 30, 140737323562752, 140737323558176}}, sa_flags = -253137552,
sa_restorer = 0x8}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00007ffff688c56d in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#3 0x00007ffff688a316 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#4 0x00007ffff688a361 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#5 0x00007ffff6889f5c in __gxx_personality_v0 () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#6 0x00007ffff62eb019 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
No symbol table info available.
#7 0x00007ffff62eb45d in _Unwind_Resume () from /lib/x86_64-linux-gnu/libgcc_s.so.1
No symbol table info available.
#8 0x00007ffff690e114 in std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#9 0x000055555558f655 in std::operator<< <char, std::char_traits<char>, std::allocator<char> > (
__str="ERR 140737235216128 12:20:16.3 UHDDevice.cpp:843:check_rx_md_err: No packet received, implementation timed-out", __os=...)
at /usr/include/c++/6/bits/basic_string.h:5345
No locals.
#10 Log::~Log (this=0x7ffff0e94d40, __in_chrg=<optimized out>) at Logger.cpp:228
No locals.
#11 0x0000555555576d7c in uhd_device::check_rx_md_err (this=this@entry=0x5555557e4190, md=..., num_smpls=num_smpls@entry=0)
at UHDDevice.cpp:843
__FUNCTION__ = "check_rx_md_err"
ticks = <optimized out>
#12 0x000055555557e1e2 in uhd_device::readSamples (this=0x5555557e4190, bufs=std::vector of length 1, capacity 1 = {...}, len=625,
overrun=<optimized out>, timestamp=680913461, underrun=<optimized out>, RSSI=0x0) at UHDDevice.cpp:929
num_smpls = 0
rc = <optimized out>
ts = {<boost::operators_impl::additive<uhd::time_spec_t, uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>, boost::operators_impl::operators_detail::false_t>> = {<boost::operators_impl::additive1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::addable1<uhd::time_spec_t, boost::operators_impl::subtractable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> > >> = {<boost::operators_impl::subtractable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <boost::operators_impl::totally_ordered<uhd::time_spec_t, uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>, boost::operators_impl::operators_detail::false_t>> = {<boost::operators_impl::totally_ordered1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::less_than_comparable1<uhd::time_spec_t, boost::operators_impl::equality_comparable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> > >> = {<boost::operators_impl::equality_comparable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, _full_secs = 2514, _frac_secs = 0.14200984615402626}
metadata = {has_time_spec = false,
time_spec = {<boost::operators_impl::additive<uhd::time_spec_t, uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>, boost::operators_impl::operators_detail::false_t>> = {<boost::operators_impl::additive1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::addable1<uhd::time_spec_t, boost::operators_impl::subtractable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> > >> = {<boost::operators_impl::subtractable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <boost::operators_impl::totally_ordered<uhd::time_spec_t, uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>, boost::operators_impl::operators_detail::false_t>> = {<boost::operators_impl::totally_ordered1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::less_than_comparable1<uhd::time_spec_t, boost::operators_impl::equality_comparable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> > >> = {<boost::operators_impl::equality_comparable1<uhd::time_spec_t, boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t> >> = {<boost::operators_impl::operators_detail::empty_base<uhd::time_spec_t>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, _full_secs = 0, _frac_secs = 0}, more_fragments = false,
fragment_offset = 0, start_of_burst = false, end_of_burst = false, error_code = uhd::rx_metadata_t::ERROR_CODE_TIMEOUT,
out_of_sequence = false}
__FUNCTION__ = "readSamples"
---Type <return> to continue, or q <return> to quit---
pkt_bufs = std::vector of length 1, capacity 1 = {std::vector of length 4088, capacity 4088 = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0...}}
pkt_ptrs = std::vector of length 1, capacity 1 = {0x7fffd400acf0}
#13 0x0000555555560b00 in RadioInterface::pullBuffer (this=0x55555582a600) at radioInterface.cpp:313
local_underrun = false
numRecv = <optimized out>
__FUNCTION__ = "pullBuffer"
#14 0x000055555555fd5e in RadioInterface::driveReceiveRadio (this=0x55555582a600) at radioInterface.cpp:229
burst = 0x0
rcvClock = {mFN = 1561772, mTN = 4}
recvSz = <optimized out>
symbolsPerSlot = <optimized out>
burstSize = <optimized out>
#15 0x0000555555565410 in Transceiver::driveReceiveRadio (this=this@entry=0x555555845f40) at Transceiver.cpp:874
No locals.
#16 0x00005555555654c8 in RxLowerLoopAdapter (transceiver=0x555555845f40) at Transceiver.cpp:1033
No locals.
#17 0x00007ffff7bc06da in start_thread (arg=0x7ffff0e96700) at pthread_create.c:456
__res = <optimized out>
pd = 0x7ffff0e96700
now = <optimized out>
unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737235216128, 3124220185394919949, 140737352381934, 140737352381935,
140737235216832, 140737235216128, -3124209075398526451, -3124202037778335219}, mask_was_saved = 0}}, priv = {pad = {
0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
not_first_call = <optimized out>
pagesize_m1 = <optimized out>
sp = <optimized out>
freesize = <optimized out>
__PRETTY_FUNCTION__ = "start_thread"
#18 0x00007ffff601cd7f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105
No locals.
Observed with latest master (f611569018f7456ff1fb7a0ffdfc2a76696702d7) and GNU C++ version 6.2.0 20161005; Boost_106100; UHD_003.009.006-release on ubuntu 17.04 x86_64.
Updated by pespin about 6 years ago
About that _Unwind_Resume:
http://www.mit.edu/~sipb-iap/2004/inside-c/day3/exceptions.html
_Unwind_Resume
Resume the unwind process, called at the end of cleanup code that didn't return to the normal thread of execution (ie, not a catch).
It seems it's also used by pthread_cancel, which osmo-trx uses.
__gxx_personality_v0 is used to handle c++ exceptions: https://stackoverflow.com/questions/329059/what-is-gxx-personality-v0-for
According to the stack trace, it was in current master (l889) "LOG << str_code(md);", which looks like a difficult place to crash sometimes.
I think the following is related. which points to some issue with pthread_cancel: https://stackoverflow.com/questions/4766768/unhandled-forced-unwind-causes-abort
Next time you see this, please run "thread apply all bt" to get a backtrace of ahh the threads so we can actually see better what's going on.
Updated by pespin about 6 years ago
Hm it seems osmo-trx it's handling thread cancellation properly (deferring cancellation and using pthread_testcancel()), which means pthread_cancel should not affect this crash afaiu. https://wiki.sei.cmu.edu/confluence/display/c/POS47-C.+Do+not+use+threads+that+can+be+canceled+asynchronously
Updated by pespin over 5 years ago
- Status changed from New to Resolved
- % Done changed from 0 to 100
I think this crash relates really closely to what I fixed lately: https://gerrit.osmocom.org/#/c/osmo-trx/+/10739/
It was merged as osmo-trx.git master 86be40b4eb762d5c12e8e3f7388ca9f254e77b36
Actions
