[Home]

Summary:ASTERISK-14344: 1.6.2.0_beta3 locks up in certain SIP scenario
Reporter:klaus3000 (klaus3000)Labels:
Date Opened:2009-06-19 12:25:53Date Closed:2011-06-07 14:01:02
Priority:BlockerRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk-1.6.2beta3-lockup-backtrace.txt
Description:Hi!

In this scenario 1.6.2.0-beta3 locks up:

--INVITE-->
<-407------
[ACK is lost]

--INVITE w/credentials-->

As soon as the second INVITE is received, chan_sip does not do anything anymore. I see SIP packets sent to asterisk but they do not show in in the log anymore.

If I make a call from dahdi to SIP I see that chan_sip sends out the INVITE request, but the incoming SIP requests are not processes by chan_sip.

I tested the above scenario and this beahvior is only in 1.6.2.0-beta3. Asterisk 1.4.25 and svn-trunk r201907 behave different, see ASTERISK-13365

****** ADDITIONAL INFORMATION ******

[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c:
<--- SIP read from UDP:88.198.53.113:5060 --->
INVITE sip:01505641636@83.136.32.165 SIP/2.0
Record-Route: <sip:88.198.53.113;lr=on;ftag=9e28df57;nat=caller>
Via: SIP/2.0/UDP 88.198.53.113;branch=z9hG4bK-d8754z-f44e95308c182711-1---d8754z-
Via: SIP/2.0/UDP 10.10.0.198:5061;rport=5061;received=83.136.33.3;branch=z9hG4bK-d8754z-f44e95308c182711-1---d8754z-
Max-Forwards: 69
Contact: <sip:klaus@83.136.33.3:5061;transport=udp>
To: "01505641636"<sip:01505641636@83.136.32.165>
From: "klaus samuel"<sip:klaus@83.136.32.165>;tag=9e28df57
Call-ID: MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: eyeBeam release 1102q stamp 51814
Content-Length: 252

v=0
o=- 0 2 IN IP4 10.10.0.198
s=CounterPath eyeBeam 1.5
c=IN IP4 88.198.53.113
t=0 0
m=audio 35018 RTP/AVP 0 8 18 101
a=fmtp:18 annexb=yes
a=fmtp:101 0-15
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=nortpproxy:yes

<------------->
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  0 [ 44]: INVITE sip:01505641636@83.136.32.165 SIP/2.0
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  1 [ 64]: Record-Route: <sip:88.198.53.113;lr=on;ftag=9e28df57;nat=caller>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  2 [ 81]: Via: SIP/2.0/UDP 88.198.53.113;branch=z9hG4bK-d8754z-f44e95308c182711-1---d8754z-
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  3 [116]: Via: SIP/2.0/UDP 10.10.0.198:5061;rport=5061;received=83.136.33.3;branch=z9hG4bK-d8754z-f44e95308c182711-1---d8754z-
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  4 [ 16]: Max-Forwards: 69
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  5 [ 51]: Contact: <sip:klaus@83.136.33.3:5061;transport=udp>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  6 [ 48]: To: "01505641636"<sip:01505641636@83.136.32.165>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  7 [ 58]: From: "klaus samuel"<sip:klaus@83.136.32.165>;tag=9e28df57
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  8 [ 53]: Call-ID: MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  9 [ 14]: CSeq: 1 INVITE
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 11 [ 29]: Content-Type: application/sdp
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 12 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 13 [ 19]: Content-Length: 252
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 14 [  0]:
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  0 [  3]: v=0
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  1 [ 26]: o=- 0 2 IN IP4 10.10.0.198
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  2 [ 25]: s=CounterPath eyeBeam 1.5
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  3 [ 22]: c=IN IP4 88.198.53.113
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  4 [  5]: t=0 0
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  5 [ 32]: m=audio 35018 RTP/AVP 0 8 18 101
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  6 [ 20]: a=fmtp:18 annexb=yes
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  7 [ 15]: a=fmtp:101 0-15
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  8 [ 21]: a=rtpmap:18 G729/8000
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  9 [ 33]: a=rtpmap:101 telephone-event/8000
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body 10 [ 10]: a=sendrecv
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body 11 [ 16]: a=nortpproxy:yes
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c: --- (14 headers 12 lines) ---
[Jun 19 19:15:45] DEBUG[16911] acl.c: Found IP address for this socket
[Jun 19 19:15:45] VERBOSE[16911] netsock.c:   == Using SIP RTP CoS mark 5
[Jun 19 19:15:45] VERBOSE[16911] netsock.c:   == Using SIP VRTP CoS mark 6
[Jun 19 19:15:45] VERBOSE[16911] netsock.c:   == Using UDPTL CoS mark 5
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Setting NAT on RTP to On
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Setting NAT on VRTP to On
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Setting NAT on UDPTL to On
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Allocating new SIP dialog for MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM. - INVITE (With RTP)
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c: Sending to 88.198.53.113 : 5060 (NAT)
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Initializing initreq for method INVITE - callid MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c: Using INVITE request as basis request - MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c: Found peer 'klaus' for 'klaus' from 88.198.53.113:5060
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Setting NAT on RTP to On
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Setting NAT on VRTP to On
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Setting NAT on UDPTL to On
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c:
<--- Reliably Transmitting (NAT) to 88.198.53.113:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 88.198.53.113;branch=z9hG4bK-d8754z-f44e95308c182711-1---d8754z-;received=88.198.53.113
Via: SIP/2.0/UDP 10.10.0.198:5061;rport=5061;received=83.136.33.3;branch=z9hG4bK-d8754z-f44e95308c182711-1---d8754z-
From: "klaus samuel"<sip:klaus@83.136.32.165>;tag=9e28df57
To: "01505641636"<sip:01505641636@83.136.32.165>;tag=as4afb6e69
Call-ID: MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
CSeq: 1 INVITE
Server: Asterisk PBX 1.6.2.0-beta3
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="83.136.32.165", nonce="12674910"
Content-Length: 0


<------------>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  ASTERISK-18
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 88.198.53.113:5060
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c: Scheduling destruction of SIP dialog 'MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.' in 32000 ms (Method: INVITE)
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c:
<--- SIP read from UDP:88.198.53.113:5060 --->
INVITE sip:01505641636@83.136.32.165 SIP/2.0
Record-Route: <sip:88.198.53.113;lr=on;ftag=9e28df57;nat=caller>
Via: SIP/2.0/UDP 88.198.53.113;branch=z9hG4bK-d8754z-042e5a7c28407a1a-1---d8754z-
Via: SIP/2.0/UDP 10.10.0.198:5061;rport=5061;received=83.136.33.3;branch=z9hG4bK-d8754z-042e5a7c28407a1a-1---d8754z-
Max-Forwards: 69
Contact: <sip:klaus@83.136.33.3:5061;transport=udp>
To: "01505641636"<sip:01505641636@83.136.32.165>
From: "klaus samuel"<sip:klaus@83.136.32.165>;tag=9e28df57
Call-ID: MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: eyeBeam release 1102q stamp 51814
Authorization: Digest username="klaus",realm="83.136.32.165",nonce="12674910",uri="sip:01505641636@83.136.32.165",response="09e9796c88249d15171ba9d1d2996977",algorithm=MD5
Content-Length: 252

v=0
o=- 0 2 IN IP4 10.10.0.198
s=CounterPath eyeBeam 1.5
c=IN IP4 88.198.53.113
t=0 0
m=audio 35018 RTP/AVP 0 8 18 101
a=fmtp:18 annexb=yes
a=fmtp:101 0-15
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=nortpproxy:yes

<------------->
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  0 [ 44]: INVITE sip:01505641636@83.136.32.165 SIP/2.0
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  1 [ 64]: Record-Route: <sip:88.198.53.113;lr=on;ftag=9e28df57;nat=caller>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  2 [ 81]: Via: SIP/2.0/UDP 88.198.53.113;branch=z9hG4bK-d8754z-042e5a7c28407a1a-1---d8754z-
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  3 [116]: Via: SIP/2.0/UDP 10.10.0.198:5061;rport=5061;received=83.136.33.3;branch=z9hG4bK-d8754z-042e5a7c28407a1a-1---d8754z-
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  4 [ 16]: Max-Forwards: 69
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  5 [ 51]: Contact: <sip:klaus@83.136.33.3:5061;transport=udp>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  6 [ 48]: To: "01505641636"<sip:01505641636@83.136.32.165>
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  7 [ 58]: From: "klaus samuel"<sip:klaus@83.136.32.165>;tag=9e28df57
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  8 [ 53]: Call-ID: MWU2ZGNhNDNjZTRmNjAzMmE4YTViNTA5ZmY0OGFiODM.
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header  9 [ 14]: CSeq: 2 INVITE
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 11 [ 29]: Content-Type: application/sdp
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 12 [ 45]: User-Agent: eyeBeam release 1102q stamp 51814
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 13 [171]: Authorization: Digest username="klaus",realm="83.136.32.165",nonce="12674910",uri="sip:01505641636@83.136.32.165",response="09e9796c88249d15171ba9d1d2996977",algorithm=MD5
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 14 [ 19]: Content-Length: 252
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:  Header 15 [  0]:
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  0 [  3]: v=0
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  1 [ 26]: o=- 0 2 IN IP4 10.10.0.198
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  2 [ 25]: s=CounterPath eyeBeam 1.5
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  3 [ 22]: c=IN IP4 88.198.53.113
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  4 [  5]: t=0 0
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  5 [ 32]: m=audio 35018 RTP/AVP 0 8 18 101
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  6 [ 20]: a=fmtp:18 annexb=yes
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  7 [ 15]: a=fmtp:101 0-15
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  8 [ 21]: a=rtpmap:18 G729/8000
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body  9 [ 33]: a=rtpmap:101 telephone-event/8000
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body 10 [ 10]: a=sendrecv
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c:    Body 11 [ 16]: a=nortpproxy:yes
[Jun 19 19:15:45] VERBOSE[16911] chan_sip.c: --- (15 headers 12 lines) ---
[Jun 19 19:15:45] DEBUG[16911] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE


Comments:By: Russell Bryant (russell) 2009-07-27 15:42:29

Can you please provide "core show locks" output for this issue?

Build Asterisk with DEBUG_THREADS enabled.  Then, when it locks up, grab the output of the "core show locks" CLI command.  That should tell us where it has locked up.
By: klaus3000 (klaus3000) 2009-07-28 01:44:10

tested with Asterisk 1.6.2.0-beta3:

After the above described scenario "core show locks":

=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: -1301283952 (do_monitor           started at [21574] chan_sip.c restart_monitor())
=== ---> Lock #0 (chan_sip.c): MUTEX 21083 handle_request_do &netlock 0xb31db8a0 (1)
       asterisk(ast_bt_get_addresses+0x19) [0x810bbd8]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31543a0]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31aea5e]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31ae7fc]
       asterisk(ast_io_wait+0x14d) [0x81017c7]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31b043a]
       asterisk [0x8186166]
       /lib/i686/cmov/libpthread.so.0 [0xb7aac4c0]
       /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb7ce16de]
=== ---> Lock #1 (chan_sip.c): MUTEX 6959 find_call sip_pvt_ptr 0xa16b8d0 (1)
       asterisk(ast_bt_get_addresses+0x19) [0x810bbd8]
       asterisk [0x8084704]
       asterisk(_ao2_lock+0x4a) [0x80845bc]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31687b5]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31aea7a]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31ae7fc]
       asterisk(ast_io_wait+0x14d) [0x81017c7]
       /usr/lib/asterisk/modules/chan_sip.so [0xb31b043a]
       asterisk [0x8186166]
       /lib/i686/cmov/libpthread.so.0 [0xb7aac4c0]
       /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb7ce16de]
=== -------------------------------------------------------------------
===
=======================================================================
By: Russell Bryant (russell) 2009-08-07 10:20:11

Hm, that's odd.  I guess now we need to know what the monitor thread is doing at this point, if it's not waiting on a lock.

Can you attach to it with gdb and get a backtrace?

# gdb asterisk `pidof asterisk`
(gdb) thread apply all bt
By: klaus3000 (klaus3000) 2009-08-10 09:23:07

I have attached the backtrace. btw: you can test it yourself by configure your SIP client to use the outboundproxy "nxdomain.at" (a SIP proxy which relays everything but drops the ACK).
By: Russell Bryant (russell) 2009-08-10 09:28:59

Thanks for the information.  The problem here is an infinite loop in SDP parsing which has already been fixed.  Specifically, it was fixed in revision 202340 in the 1.6.2 branch.

1.6.2.0-beta3 has the bug.  1.6.2.0-beta4 has the fix.