Summary: | ASTERISK-26373: channel: Crash when appending cap during dialing to a channel, when built with debugging compiler options | ||
Reporter: | Denis S.Davydov (denis.davydov) | Labels: | |
Date Opened: | 2016-09-14 03:55:12 | Date Closed: | 2018-07-11 04:38:47 |
Priority: | Major | Regression? | |
Status: | Closed/Complete | Components: | Core/Channels |
Versions: | 13.11.2 | Frequency of Occurrence | |
Related Issues: | |||
Environment: | Virtual Machine on ESXi6 (VM Version 11, 4vCPU, 16Gb RAM), OS: CentOS release 6.8 (Final) x86_84 | Attachments: | ( 0) 20160913_1457.log ( 1) bt_20160927.log ( 2) full_20160913_1457.txt ( 3) full_20160927.log ( 4) full_filtered_20160927.log ( 5) mmlog_20160913 ( 6) queue_20160927.log |
Description: | Sep 13 14:57:23 pbx kernel: asterisk[18303] general protection ip:526f83 sp:7fa6e1854340 error:0 in asterisk[400000+370000]
Segmentation fault in ast_format_cap_append_from_cap. {code} Program terminated with signal 11, Segmentation fault. #0 0x0000000000526f83 in ast_format_cap_append_from_cap (dst=0x7fa731384ab0, src=0x7fa6d5098350, type=AST_MEDIA_TYPE_UNKNOWN) at format_cap.c:308 308 struct format_cap_framed *framed = AST_VECTOR_GET(&src->preference_order, idx); #0 0x0000000000526f83 in ast_format_cap_append_from_cap (dst=0x7fa731384ab0, src=0x7fa6d5098350, type=AST_MEDIA_TYPE_UNKNOWN) at format_cap.c:308 __idx = 0 framed = 0x7fa6d512f190 idx = 0 res = 0 #1 0x00000000004c2e53 in ast_request (type=0x7fa6e1854580 "SIP", request_cap=0x7fa6d5098350, assignedids=0x0, requestor=0x7fa6d54b3068, addr=0x7fa6e1854584 "3112", cause=0x7fa6e1854680) at channel.c:6068 tmp_cap = 0x7fa7313bf700 tmp_fmt = 0xbc67d0 best_audio_fmt = 0xbc67d0 joint_cap = 0x7fa731384ab0 chan = 0x17a62c0 c = 0x7fa6e1855fc0 res = 0 foo = 32679 __PRETTY_FUNCTION__ = "ast_request" {code} backtrace.txt and full.txt are in attachment. Compiled flags on my Asterisk-PBX is DONT_OPTIMIZE, COMPILE_DOUBLE, LOADABLE_MODULES, BETTER_BACKTRACES, MALLOC_DEBUG, BULD_NATIVE. Mmlog useless, there's nothing. | ||
Comments: | By: Asterisk Team (asteriskteam) 2016-09-14 03:55:12.679-0500 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. By: Denis S.Davydov (denis.davydov) 2016-09-14 03:57:12.395-0500 Yesterday I have four times crash issues like this one. This is Asterisk on production :( By: Rusty Newton (rnewton) 2016-09-14 09:57:33.801-0500 Does the full log end at the crash? Did this start happening after an upgrade to a particular version? By: Denis S.Davydov (denis.davydov) 2016-09-15 00:44:27.577-0500 bzgrep -B15000 -A1000 'by root' /var/log/asterisk/full-20160913-1473786061.bz2 > full_20160913_1457.txt So the last 21 rows before crash was: {code} [Sep 13 14:57:23] DEBUG[12792] app_queue.c: Device 'SIP/3111' changed to state '1' (Not in use) [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa7222eddf8 refcount now 2 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] chan_sip.c: Acked pending invite 105 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] chan_sip.c: Stopping retransmission on 'zko1lkuokmbz19009b1an0z8lo1uoljx@SoftX3000' of Request 105: Match Found [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6bc000d18 refcount now 2 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6ec5e2318 refcount now 2 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6e8000dd8 refcount now 2 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6ee0869f8 refcount now 2 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa7154e8608 refcount now 2 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa7222eddf8 refcount now 2 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fa73c0a2030 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fa73c0a2030 [Sep 13 14:57:23] DEBUG[18303][C-00000fb7] app_queue.c: Trying 'SIP/3112' with metric 4 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6d5500ed8' [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6bc000d18 refcount now 2 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] rtp_engine.c: Copying payload 8 (0x7fa6d4234ea0) from 0x7fa73c0a2030 to 0x7fa6d55010a0 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6ec5e2318 refcount now 2 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] rtp_engine.c: Copying payload 101 (0x7fa6d404fe20) from 0x7fa73c0a2030 to 0x7fa6d55010a0 [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6e8000dd8 refcount now 2 [Sep 13 14:57:23] DEBUG[12786][C-00000fb7] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fa6d5500ed8' [Sep 13 14:57:23] DEBUG[12779] manager.c: Mansession: 0x7fa6ee0869f8 refcount now 2 [Sep 13 14:57:29] Asterisk 13.11.2 built by root @ pbx.autoconnex.ru on a x86_64 running Linux on 2016-09-12 20:10:17 UTC {code} I have upgraded Asterisk from 13.10-rc1 to 13.11.2 with enabling debug options (early I have not debug options on my 13.10-rc1). By: Denis S.Davydov (denis.davydov) 2016-09-22 00:44:35.351-0500 This is strange! But crashes does not occur again after I rebuilt Asterisk excluding these parameters: --enable DONT_OPTIMIZE \ --enable BETTER_BACKTRACES \ --enable MALLOC_DEBUG \ :) To see the frequency of last accidents following: {code} $ ls -ltr /data/tmp/core-asterisk-11-0-0-* -rw------- 1 root root 654843904 Sep 13 09:16 /data/tmp/core-asterisk-11-0-0-21797-1473758164 -rw------- 1 root root 156868608 Sep 13 09:17 /data/tmp/core-asterisk-11-0-0-8487-1473758271 -rw------- 1 root root 229892096 Sep 13 09:49 /data/tmp/core-asterisk-11-0-0-8816-1473760145 -rw------- 1 root root 775057408 Sep 13 14:57 /data/tmp/core-asterisk-11-0-0-12760-1473778643 -rw------- 1 root root 1149308928 Sep 14 13:56 /data/tmp/core-asterisk-11-0-0-23807-1473861417 -rw------- 1 root root 821338112 Sep 15 07:26 /data/tmp/core-asterisk-11-0-0-5189-1473924415 -rw------- 1 root root 606130176 Sep 15 11:30 /data/tmp/core-asterisk-11-0-0-14960-1473939034 -rw------- 1 root root 172089344 Sep 15 11:34 /data/tmp/core-asterisk-11-0-0-11633-1473939274 -rw------- 1 root root 125165568 Sep 15 11:35 /data/tmp/core-asterisk-11-0-0-12237-1473939337 -rw------- 1 root root 612769792 Sep 15 15:28 /data/tmp/core-asterisk-11-0-0-12418-1473953330 -rw------- 1 root root 156487680 Sep 15 15:32 /data/tmp/core-asterisk-11-0-0-9172-1473953519 -rw------- 1 root root 527540224 Sep 16 05:40 /data/tmp/core-asterisk-11-0-0-9648-1474004432 -rw------- 1 root root 249794560 Sep 16 07:05 /data/tmp/core-asterisk-11-0-0-29189-1474009559 -rw------- 1 root root 401727488 Sep 16 09:21 /data/tmp/core-asterisk-11-0-0-5569-1474017671 -rw------- 1 root root 1367691264 Sep 17 18:54 /data/tmp/core-asterisk-11-0-0-3437-1474138469 -rw------- 1 root root 881455104 Sep 18 12:27 /data/tmp/core-asterisk-11-0-0-9423-1474201667 -rw------- 1 root root 129671168 Sep 19 02:31 /data/tmp/core-asterisk-11-0-0-11556-1474252278 -rw------- 1 root root 198107136 Sep 19 05:06 /data/tmp/core-asterisk-11-0-0-18144-1474261600 -rw------- 1 root root 608952320 Sep 19 09:44 /data/tmp/core-asterisk-11-0-0-27734-1474278267 -rw------- 1 root root 171937792 Sep 19 09:50 /data/tmp/core-asterisk-11-0-0-25708-1474278648 -rw------- 1 root root 175071232 Sep 19 09:59 /data/tmp/core-asterisk-11-0-0-26470-1474279180 -rw------- 1 root root 288841728 Sep 19 11:13 /data/tmp/core-asterisk-11-0-0-27725-1474283584 -rw------- 1 root root 242311168 Sep 19 11:55 /data/tmp/core-asterisk-11-0-0-4450-1474286131 -rw------- 1 root root 145694720 Sep 19 11:58 /data/tmp/core-asterisk-11-0-0-9887-1474286299 -rw------- 1 root root 190824448 Sep 19 12:09 /data/tmp/core-asterisk-11-0-0-10292-1474286981 -rw------- 1 root root 231333888 Sep 19 12:42 /data/tmp/core-asterisk-11-0-0-12044-1474288921 {code} At the 19/09 I've rebuilt Asterisk the same Asterisk 13.11.2 without debug options and now have no crashes yet. By: Rusty Newton (rnewton) 2016-09-22 09:36:33.609-0500 Thanks. That information is really useful. If you can, go ahead and attach all your asterisk configs (any that are changed from the samples or that are not blank) and simply sanitize any private information. By: Denis S.Davydov (denis.davydov) 2016-09-27 06:22:51.937-0500 Today was a crash. The last crash has been at 19/09/16 12:42. So here is details: {code} Core was generated by `/usr/local/asterisk-13.11.2.nodebug/sbin/asterisk -f -vvvg -c'. Program terminated with signal 11, Segmentation fault. #0 ast_format_cap_append_from_cap (dst=0x7f6dcadc6d60, src=0x7f6dfab69990, type=AST_MEDIA_TYPE_AUDIO) at format_cap.c:308 308 struct format_cap_framed *framed = AST_VECTOR_GET(&src->preference_order, idx); #0 ast_format_cap_append_from_cap (dst=0x7f6dcadc6d60, src=0x7f6dfab69990, type=AST_MEDIA_TYPE_AUDIO) at format_cap.c:308 __idx = 0 framed = <value optimized out> idx = <value optimized out> res = <value optimized out> #1 0x00000000004aad10 in ast_request (type=0x7f6df1f75cd0 "SIP", request_cap=0x7f6dfab69990, assignedids=0x0, requestor=0x7f6dfb4e9288, addr=0x7f6df1f75cd4 "3124", cause=0x7f6df1f75ecc) at channel.c:6037 tmp_cap = 0x7f6dcadc6d60 tmp_fmt = 0x0 best_audio_fmt = 0x0 joint_cap = <value optimized out> chan = 0x2386c50 c = <value optimized out> res = <value optimized out> foo = 32621 __PRETTY_FUNCTION__ = "ast_request" #2 0x00007f6e6c366083 in ring_entry (qe=0x7f6df1f77360, tmp=0x7f6dcacb2460, busies=0x7f6df1f76cb8) at app_queue.c:4317 res = <value optimized out> status = 0 tech = "SIP\000\063\061\062\064\000\250\000\000\000\000\000\000\000\030\350\312m\177\000\000\320\001\000\000\000\000\000\000 \341x\331\t\000\000\000\"\253G\331\070\000\000\000\000\030\350\312m\177\000\000\240O\326\312m\177\000\000\320\001\000\000\000\000\000\000\270\252\330\312m\177\000\000\310L\325\312m\177\000\000\270\252\330\312m\177\000\000\210O\326\312m\177\000\000\f\213^\000\000\000\000\000\003\000\000\000\034\000\000\000\b\000\000\000\033\000\000\000\b\000\000\000t\000\000\000\002\000\000\000\016\001", '\000' <repeats 26 times>"\301, \207\002\000\000\000\000\000\223-\352W\000\000\000\000\301\207\002\000\000\000\000\000\223-\352W\000\000\000\000\301\207\002\000\000\000\000\000q\021\000\000\000\000\000\000\320P\312\312m\177\000\000\244\230\067ln\177\000\000\260\335F\373m\177\000\000\000\000\000\000\000\000\000\000L\217\067ln\177\000" location = 0x7f6df1f75cd4 "3124" macrocontext = <value optimized out> macroexten = <value optimized out> blob = 0x0 __PRETTY_FUNCTION__ = "ring_entry" {code} Suspect that it caused by call on 3124 via queue. I've attached log files. Incoming call was from 9057565964 to 4957390491. Configuration for that call is as follows: sip.conf: {code} [general] transport=udp allowguest=no allowoverlap=no language=ru compactheaders=no rtptimeout=60 rtpholdtimeout=300 session-timers=refuse callcounter=yes directmedia=no directrtpsetup=no rtcachefriends=yes rtupdate=yes rtautoclear=no rtautoclear=no ignoreregexpire=yes allowsubscribe=yes alwaysauthreject=yes use_q850_reason=yes faxdetect=no t38pt_udptl=no sendrpid=rpid trustrpid=yes nat=force_rport,comedia progressinband=yes externip=X.X.X.X localnet=192.168.0.0/255.255.0.0 localnet=212.248.28.10 [mts] type=peer trunkname=mts host=212.248.28.10 context=from-trunk insecure=port,invite disallow=all allow = alaw,ulaw nat = no directmedia = no dtmfmode = rfc2833 qualify=yes [friend](!) type=friend host=dynamic secret=verysecret context=from-phone t38pt_usertpsource=yes insecure=invite,port directmedia=no disallow=all allow=ulaw,alaw,g722,g729 qualify=yes canreinvite=yes busylevel=1 dtmfmode=rfc2833 deny = 0.0.0.0/0.0.0.0 permit = 192.168.0.0/255.255.0.0 ... [3012](friend) callerid=ALICE <3012> accountcode=3012 [3012](friend) callerid=BOB <3013> accountcode=3013 {code} We've got direct link for this provider, so it is on localnet (212.248.28.10 accessed via private address). extensions.conf: {code} [from-trunk] exten = _X.,1,Set(CDR(direction)=2) same = n,Set(GROUP()=lines_${CHANNEL(peername)}) same = n,Verbose(1,Incoming call from ${CDR(src)} to ${EXTEN} via ${CHANNEL(peername)}) same = n,Verbose(1,Concurent lines on ${CHANNEL(peername)} is ${GROUP_COUNT(lines_${CHANNEL(peername)})}) same = n,GotoIf($[${BLACKLIST()}]?blocked,1) same = n,Gosub(record,${EXTEN},2) same = n,Goto(incoming,${EXTEN},1) [incoming] exten = 4957390491,1,Goto(otp,s,1) [otp] exten = s,1,Answer same = n,Background(/usr/local/asterisk/var/lib/asterisk/sounds/ru/ivr/9) same = n,WaitExten(2) same = n,Goto(otp,1,1) same = n,Hangup() exten = 1,1,NoOp() same = n,Set(__WAIT4ANSWER=${EPOCH}) same = n,Queue(OTP_3602,t,,,300,,,wait4answer) same = n,Hangup() exten = 2,1,Goto(otp,1,1) exten = i,1,Playback(invalid) same = n,Goto(otp,s,1) exten = t,1,Playback(vm-goodbye) same = n,Hangup() {code} queues.conf: {code} [general] monitor-type = MixMonitor persistentmembers = yes setinterfacevar=yes setqueueentryvar=yes setqueuevar=yes [queue_template](!) musicclass=default musiconhold=default joinempty=yes leavewhenempty=no strategy=rrmemory retry = 1 [OTP_3602](queue_template) timeout = 14 periodic-announce = /usr/local/asterisk/var/lib/asterisk/sounds/ru/ivr/8 periodic-announce-frequency = 30 relative-periodic-announce = yes announce-holdtime = no {code} Prefered codec on the phones: g722, ulaw, alaw, g729. Information for peer 3124: {code} # asterisk -rx 'sip show peer 3124' * Name : 3124 Description : Secret : <Set> MD5Secret : <Not set> Remote Secret: <Not set> Context : from-phone Record On feature : automon Record Off feature : automon Subscr.Cont. : <Not set> Language : ru Tonezone : <Not set> Accountcode : 3124 AMA flags : Unknown Transfer mode: open CallingPres : Presentation Allowed, Not Screened Callgroup : Pickupgroup : Named Callgr : Nam. Pickupgr: MOH Suggest : Mailbox : VM Extension : asterisk LastMsgsSent : 0/0 Call limit : 2147483647 Max forwards : 0 Busy level : 1 Dynamic : Yes Callerid : "ТЕХЭКСПЕРТ" <3124> MaxCallBR : 384 kbps Expire : 1622 Insecure : port,invite Force rport : Yes Symmetric RTP: Yes ACL : Yes DirectMedACL : No T.38 support : No T.38 EC mode : Unknown T.38 MaxDtgrm: 4294967295 DirectMedia : Yes PromiscRedir : No User=Phone : No Video Support: No Text Support : No Ign SDP ver : No Trust RPID : Yes Send RPID : Yes Path support : No Path : N/A TrustIDOutbnd: Legacy Subscriptions: Yes Overlap dial : No DTMFmode : rfc2833 Timer T1 : 500 Timer B : 32000 ToHost : Addr->IP : 192.168.60.103:5060 Defaddr->IP : (null) Prim.Transp. : UDP Allowed.Trsp : UDP Def. Username: 3124 SIP Options : path replaces replace timer Codecs : (ulaw|alaw|g722|g729) Auto-Framing : No Status : OK (13 ms) Useragent : Grandstream GXP1628 0.8.16.42 Reg. Contact : sip:3124@192.168.60.103:5060 Qualify Freq : 60000 ms Keepalive : 0 ms Variables : LDC = 1 Sess-Timers : Refuse Sess-Refresh : uas Sess-Expires : 1800 secs Min-Sess : 90 secs RTP Engine : asterisk Parkinglot : Use Reason : Yes Encryption : No {code} By: Denis S.Davydov (denis.davydov) 2016-09-27 06:29:07.341-0500 Just in case. A snippet from my ast_build.sh (if you wish to see build options): {code} make dist-clean ./bootstrap.sh ./configure --prefix=${ASTERISK_INSTALL_DIR} make menuselect.makeopts menuselect/menuselect \ --enable format_mp3 \ --enable res_config_mysql \ --enable app_fax \ --enable app_ivrdemo \ --enable res_chan_stats \ --enable CORE-SOUNDS-EN-ULAW \ --enable CORE-SOUNDS-EN-ALAW \ --enable CORE-SOUNDS-EN-G729 \ --enable CORE-SOUNDS-EN-G722 \ --enable CORE-SOUNDS-EN-SLN16 \ --enable CORE-SOUNDS-RU-ULAW \ --enable CORE-SOUNDS-RU-ALAW \ --enable CORE-SOUNDS-RU-GSM \ --enable CORE-SOUNDS-RU-G729 \ --enable CORE-SOUNDS-RU-G722 \ --enable CORE-SOUNDS-RU-SLN16 \ --enable EXTRA-SOUNDS-EN-ULAW \ --enable EXTRA-SOUNDS-EN-ALAW \ --enable EXTRA-SOUNDS-EN-GSM \ --enable EXTRA-SOUNDS-EN-G729 \ --enable EXTRA-SOUNDS-EN-G722 \ --enable EXTRA-SOUNDS-EN-SLN16 \ --enable-category MENUSELECT_MOH \ menuselect.makeopts ... {code} By: Denis S.Davydov (denis.davydov) 2016-09-27 06:36:53.265-0500 bt_20160927.log - Backtrace for today's crash full_20160927.log - Full log with last 50000 lines of full.log before Asterisk been crashed full_filtered_20160927.log - Filtered full log of suspicious session C-0000343b queue_20160927.log - Queue log of suspicious session By: Corey Farrell (coreyfarrell) 2017-12-19 19:58:58.984-0600 MALLOC_DEBUG causes memory to be overwritten during the call to ast_free. It sounds like you may be using memory after it has been freed, MALLOC_DEBUG actually makes use after free much more likely to cause a crash. A reference count debugging log might be helpful. The objects you are dealing with are reference counted, I believe we're looking for something releasing a reference that it didn't have, so the object got freed while it was still in use. https://wiki.asterisk.org/wiki/display/AST/Reference+Count+Debugging By: Joshua C. Colp (jcolp) 2018-07-11 04:38:47.131-0500 Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1]. [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines |