[asterisk-dev] [Code Review] Queue SIP requests/responses that cannot be immediately processed.

Wed Jan 7 07:00:14 CST 2009

Hi!

I also found out, that Asterisk generates a wrong reponse in case the 
error happens.

Asterisk sends INVITE
Asterisk receives 100 trying and fails to grab channel lock and responds 
to 100 trying with 503

see trace below. Maybe this needs to be fixed too

regards
klaus

[Jan  7 13:39:37] VERBOSE[8535] logger.c: Reliably Transmitting (no NAT) 
to 1.2.3.183:5060:
INVITE sip:+43720123456789 at 1.2.3.183 SIP/2.0
Via: SIP/2.0/UDP 1.2.3.184:5160;branch=z9hG4bK15a53c76;rport
From: "app aster" <sip:1234 at 1.2.3.184:5160>;tag=as3001c681
To: <sip:+43720123456789 at 1.2.3.183>
Contact: <sip:1234 at 1.2.3.184:5160>
Call-ID: 2116cbb23137a8f91003bb3446862725 at 1.2.3.184
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Wed, 07 Jan 2009 12:39:37 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
X-OFIS-AU: +431234567
X-OFIS-ENUMOUT: 1
Content-Type: application/sdp
Content-Length: 285

v=0
o=root 864 864 IN IP4 1.2.3.184
s=session
c=IN IP4 1.2.3.184
t=0 0
m=audio 13172 RTP/AVP 0 3 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jan  7 13:39:37] DEBUG[8535] chan_sip.c: *** SIP TIMER: Initializing 
retransmit timer on packet: Id  #-1
[Jan  7 13:39:37] VERBOSE[876] logger.c:
<--- SIP read from 1.2.3.183:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 
1.2.3.184:5160;branch=z9hG4bK15a53c76;received=1.2.3.184;rport=5160
From: "app aster" <sip:1234 at 1.2.3.184:5160>;tag=as3001c681
To: <sip:+43720123456789 at 1.2.3.183>
Call-ID: 2116cbb23137a8f91003bb3446862725 at 1.2.3.184
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:+43720123456789 at 1.2.3.183>
Content-Length: 0

<------------->
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 0: SIP/2.0 100 Trying (18)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 1: Via: SIP/2.0/UDP 
1.2.3.184:5160;branch=z9hG4bK15a53c76;received=1.2.3.184;rport=5160 (92)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 2: From: "app aster" 
<sip:1234 at 1.2.3.184:5160>;tag=as3001c681 (62)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 3: To: 
<sip:+43720123456789 at 1.2.3.183> (39)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 4: Call-ID: 
2116cbb23137a8f91003bb3446862725 at 1.2.3.184 (55)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 5: CSeq: 102 INVITE (16)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 6: User-Agent: Asterisk 
PBX (24)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 7: Allow: INVITE, ACK, 
CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 8: Supported: replaces (19)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 9: Contact: 
<sip:+43720123456789 at 1.2.3.183> (44)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 10: Content-Length: 0 (17)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Header 11:  (0)
[Jan  7 13:39:37] VERBOSE[876] logger.c: --- (11 headers 0 lines) ---
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: = Found Their Call ID: 
2116cbb23137a8f91003bb3446862725 at 1.2.3.184 Their Tag  Our tag: as3001c681
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Failed to grab owner channel 
lock, trying again. (SIP call 2116cbb23137a8f91003bb3446862725 at 1.2.3.184)
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: = Found Their Call ID: 
2116cbb23137a8f91003bb3446862725 at 1.2.3.184 Their Tag  Our tag: as3001c681
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Failed to grab owner channel 
lock, trying again. (SIP call 2116cbb23137a8f91003bb3446862725 at 1.2.3.184)
...
[Jan  7 13:39:37] DEBUG[876] chan_sip.c: Failed to grab owner channel 
lock. (SIP call 2116cbb23137a8f91003bb3446862725 at 1.2.3.184)
[Jan  7 13:39:37] ERROR[876] chan_sip.c: We could NOT get the channel 
lock for SIP/gw-asterisk-09ca2b98!
[Jan  7 13:39:37] ERROR[876] chan_sip.c: SIP transaction failed: 
2116cbb23137a8f91003bb3446862725 at 1.2.3.184
[Jan  7 13:39:37] VERBOSE[876] logger.c:
<--- Transmitting (no NAT) to 1.2.3.183:5060 --->
SIP/2.0 503 Server error
Via: SIP/2.0/UDP 
1.2.3.184:5160;branch=z9hG4bK15a53c76;received=1.2.3.184;rport=5160;received=1.2.3.183
From: "app aster" <sip:1234 at 1.2.3.184:5160>;tag=as3001c681
To: <sip:+43720123456789 at 1.2.3.183>
Call-ID: 2116cbb23137a8f91003bb3446862725 at 1.2.3.184
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1234 at 1.2.3.184:5160>
Content-Length: 0

Kevin Fleming schrieb:
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> http://reviewboard.digium.com/r/117/
> -----------------------------------------------------------
> 
> Review request for Asterisk Developers.
> 
> 
> Summary
> -------
> 
> When a request or response arrives in sipsock_read(), and the associated sip_pvt has an ast_channel (owner), sipsock_read() attempts to obtain the channel's lock. However, this can fail if the channel is locked by another thread, which could be the case for an extended period of time (multiple microseconds, if not longer). sipsock_read() tries to work around this issue by retrying (up to 100 times) to obtain the lock, but if it still fails, the incoming message is unceremoniously dropped, under the assumption that the other endpoint will retransmit if needed. If this occurs, a message is logged to the console.
> 
> As it turns out, this is a rather common occurrence, because when an incoming call is answered via the diaplan, a '200 OK' is sent to the UAC that originated the call, which will likely result in an *immediate* 'ACK' response from the UAC. However, the channel answer process might not actually be completed, especially if it involves creation of translator paths, and so the 'ACK' is dropped, generating an error message and requiring the retransmission of both the '200 OK' and the 'ACK'.
> 
> This commit would change sipsock_read() to instead queue requests that cannot be processed immediately; queued requests will be processed either when a timer expires (no more than 10 milliseconds later), or when another request arrives and sipsock_read() was able to obtain the channel lock. In either situation, requests will be processed in the order they were received.
> 
> 
> Diffs
> -----
> 
>   /branches/1.4/channels/chan_sip.c 167370 
> 
> Diff: http://reviewboard.digium.com/r/117/diff
> 
> 
> Testing
> -------
> 
> A small amount of testing was done on Shaun Ruffell's transcoder test system, which was exhibiting this problem for every single call that required creation of a transcoder-based translation path. These changes solved his issues regarding SIP message loss and retransmission and did not exhibit any negative effects.
> 
> 
> Thanks,
> 
> Kevin
> 
> 
> _______________________________________________
> --Bandwidth and Colocation Provided by http://www.api-digital.com--
> 
> asterisk-dev mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-dev