[Home]

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:12Date Closed:2018-07-11 04:38:47
Priority:MajorRegression?
Status:Closed/CompleteComponents: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_84Attachments:( 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