ASTERISK-13292: reinvite while ringing

[Home]

Summary: ASTERISK-13292: reinvite while ringing

Reporter: Fabrizio Lombardozzi (fabrizio_lombardozzi) Labels:

Date Opened: 2009-01-02 09:56:13.000-0600 Date Closed: 2011-06-07 14:07:54

Priority: Minor Regression? No

Status: Closed/Complete Components: Channels/chan_sip/General

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) full_1.6.1.0
( 1) full_NOK
( 2) full_P.3
( 3) full_sip_debug_and_console.txt

Description: Shortly:
I've noticed that occasionally, less than 10% of the times, missing re-nvite handling
cause calls to finish unexpectedly (P.3),
other times (about 20%) minor irregularities do not cause any real problem (P.2),
while most of the times it works fine (P.1)
It seems to be strongly related (and maybe introduced) with the solution of ASTERISK-9249305.
I'm also proposing a tiny patch, that worked for me, but I'm not sure that is good for all.

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

Scenario:
Server A (Asterisk 1.6.0.1) receives a pstn call via its own TE410P
end execute from the dialplan something like "dial sip/UA@ServerB"
to transfer the call to the softphone "UA" registered on Server B (Asterisk 1.4.11).
All the ip entities (servers and ua) are same lan.

P.1: The normal thing that should happen is in the following sip history:

---------- SIP HISTORY for '4409ce143915140d5613b4e64ffadd94@10.43.100.206'
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: * SIP Call
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 001. NewChan Channel SIP/sip.sociale.it-09ec7148 - from 4409ce143915140d5613
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - -UNKNOWN-
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 Trying
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 180 Ringing
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 183 Session Progress
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 006. Rx SIP/2.0 / 102 INVITE / 200 OK
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 007. TxReq ACK / 102 ACK - -UNKNOWN-
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 008. Rx INVITE / 102 INVITE / sip:000020090102123802@10.43.100.206
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 009. ReInv Re-invite received
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 010. TxResp SIP/2.0 / 102 INVITE - 100 Trying
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 011. TxRespRel SIP/2.0 / 102 INVITE - 200 OK
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 012. Rx ACK / 102 ACK / sip:000020090102123802@10.43.100.206
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 013. Rx INVITE / 103 INVITE / sip:000020090102123802@10.43.100.206
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 014. ReInv Re-invite received
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 015. TxResp SIP/2.0 / 103 INVITE - 100 Trying
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 016. TxRespRel SIP/2.0 / 103 INVITE - 200 OK
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 017. Rx ACK / 103 ACK / sip:000020090102123802@10.43.100.206
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 018. Rx BYE / 104 BYE / sip:000020090102123802@10.43.100.206
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 019. RTCPaudio Quality:ssrc=2098904022;themssrc=1584169882;lp=34619;rxjitter=0
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 020. TxResp SIP/2.0 / 104 BYE - 200 OK
[Jan 2 12:38:58] DEBUG[9587] chan_sip.c: 021. Hangup Cause Normal Clearing
---------- END SIP HISTORY

P.2: Quite often during the transfer of above a minor fault happens:
a second (103) INVITE is sent too early, before the "102 INVITE" is acked,
and this is causing answer "103 INVITE / 491 Request Pending"
but more than half of the times (of this 20%) the Re-Invite is "substantially" completed anyway,
being the call transferred to the UA (and they can talk al they like!)
as follows in SIP HISTORY:

---------- SIP HISTORY for '0ae66c7d4715d4566e0775f908eceb01@10.43.100.206'
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: * SIP Call
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 001. NewChan Channel SIP/astw02.sociale.it-b7dc3110 - from 0ae66c7d4715d4566
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - -UNKNOWN-
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 Trying
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 180 Ringing
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 183 Session Progress
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 006. Rx SIP/2.0 / 102 INVITE / 200 OK
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 007. TxReq ACK / 102 ACK - -UNKNOWN-
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 008. Rx INVITE / 102 INVITE / sip:000020090102123917@10.43.100.206
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 009. TxReqRel INVITE / 103 INVITE - -UNKNOWN-
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 010. Rx SIP/2.0 / 103 INVITE / 491 Request Pending
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 011. TxReq ACK / 103 ACK - -UNKNOWN-
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 012. Rx INVITE / 102 INVITE / sip:000020090102123917@10.43.100.206
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 013. TxResp SIP/2.0 / 102 INVITE - 100 Trying
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 014. TxResp SIP/2.0 / 102 INVITE - 200 OK
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 015. Rx ACK / 102 ACK / sip:000020090102123917@10.43.100.206
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 016. Hangup Cause Interworking, unspecified
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 017. SchedDestroy 3200 ms
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 018. TxReqRel BYE / 104 BYE - -UNKNOWN-
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 019. RTCPaudio Quality:ssrc=435949490;themssrc=1416339997;lp=7950;rxjitter=0.0
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c: 020. Rx SIP/2.0 / 104 BYE / 200 OK
[Jan 2 12:39:52] DEBUG[9587] chan_sip.c:
---------- END SIP HISTORY for '0ae66c7d4715d4566e0775f908eceb01@10.43.100.206'

P.3: The real problem is when the "103 INVITE / 491 Request Pending" originates a "second" sip call
that always fails (but this is a normal consequence) because of missing autentication.
I've notice that this always appens when the p->owner->_state (in chan_sip.c) is equal to AST_STATE_RINGING
instead of AST_STATE_UP as expected.
And this in deatils:

---------- SIP HISTORY for '393fd9cf638fd91a6dcdd3787ff721f6@10.43.100.206'
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: * SIP Call
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 001. NewChan Channel SIP/astw06.sociale.it-083957a8 - from 393fd9cf638fd91a6
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - -UNKNOWN-
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 Trying
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 180 Ringing
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 183 Session Progress
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 006. Rx SIP/2.0 / 102 INVITE / 200 OK
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 007. TxReq ACK / 102 ACK - -UNKNOWN-
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 008. Rx INVITE / 102 INVITE / sip:000020081230102836@10.43.100.206
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 009. TxReqRel INVITE / 103 INVITE - -UNKNOWN-
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 010. Rx SIP/2.0 / 103 INVITE / 491 Request Pending
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 011. TxReq ACK / 103 ACK - -UNKNOWN-
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 012. Hangup Cause Normal Clearing
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 013. SchedDestroy 3200 ms
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 014. TxReqRel BYE / 104 BYE - -UNKNOWN-
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 015. RTCPaudio Quality:ssrc=1803864967;themssrc=634234716;lp=0;rxjitter=0.0000
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c: 016. Rx SIP/2.0 / 104 BYE / 200 OK
[Dec 30 10:29:35] DEBUG[29345] chan_sip.c:
---------- END SIP HISTORY for '393fd9cf638fd91a6dcdd3787ff721f6@10.43.100.206'

"second":
---------- SIP HISTORY for '393fd9cf638fd91a6dcdd3787ff721f6@10.43.100.206'
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: * SIP Call
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 001. Rx INVITE / 102 INVITE / sip:000020081230102836@10.43.100.206
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 002. AuthChal Auth challenge sent for - nc 0
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 003. TxRespRel SIP/2.0 / 102 INVITE - 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 004. SchedDestroy 3200 ms
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 005. ReTx 100 SIP/2.0 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 006. ReTx 200 SIP/2.0 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 007. ReTx 400 SIP/2.0 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 008. ReTx 800 SIP/2.0 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 009. ReTx 1600 SIP/2.0 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 010. ReTx 3200 SIP/2.0 401 Unauthorized
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 011. ReliableXmit timeout
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 012. MaxRetries (Non-critical)
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c: 013. AutoDestroy 393fd9cf638fd91a6dcdd3787ff721f6@10.43.100.206
[Dec 30 10:29:42] DEBUG[29345] chan_sip.c:
---------- END SIP HISTORY for '393fd9cf638fd91a6dcdd3787ff721f6@10.43.100.206'

So I (brutely) changed the "reinvite" condition in case of "491 Request Pending" for INVITE,
and now in case of "reinvite while ringing" it behaves:

---------- SIP HISTORY for '1a41047c229fc27f5ab73b396101b1f2@10.43.100.206'
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: * SIP Call
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 001. NewChan Channel SIP/astw01.sociale.it-b7dcbcb0 - from 1a41047c229fc27f5
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - -UNKNOWN-
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 Trying
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 180 Ringing
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 183 Session Progress
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 006. Rx SIP/2.0 / 102 INVITE / 200 OK
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 007. TxReq ACK / 102 ACK - -UNKNOWN-
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 008. Rx INVITE / 102 INVITE / sip:000020090102124314@10.43.100.206
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 009. TxReqRel INVITE / 103 INVITE - -UNKNOWN-
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 010. Rx SIP/2.0 / 103 INVITE / 491 Request Pending
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 011. TxReq ACK / 103 ACK - -UNKNOWN-
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 012. Rx INVITE / 102 INVITE / sip:000020090102124314@10.43.100.206
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 013. TxResp SIP/2.0 / 102 INVITE - 100 Trying
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 014. TxResp SIP/2.0 / 102 INVITE - 200 OK
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 015. Rx ACK / 102 ACK / sip:000020090102124314@10.43.100.206
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 016. Hangup Cause Normal Clearing
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 017. SchedDestroy 3200 ms
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 018. TxReqRel BYE / 104 BYE - -UNKNOWN-
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 019. RTCPaudio Quality:ssrc=1263614400;themssrc=806741475;lp=5679;rxjitter=0.0
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c: 020. Rx SIP/2.0 / 104 BYE / 200 OK
[Jan 2 12:47:20] DEBUG[9587] chan_sip.c:
---------- END SIP HISTORY for '1a41047c229fc27f5ab73b396101b1f2@10.43.100.206'

and the call is substantially (fab-)reinvited!

(even if RFC 3261, section 14.1:
Note that a UAC MUST NOT initiate a new INVITE transaction within a
dialog while another INVITE transaction is in progress in either
direction.)

Thanks for your time.
Fabrizio

Comments: By: Joshua C. Colp (jcolp) 2009-01-26 16:11:25.000-0600

Can you please try the latest revision of things? After looking at this I believe it has already been solved.
By: Joshua C. Colp (jcolp) 2009-02-26 12:07:25.000-0600

Closed due to lack of response and strong belief that this has been solved already.
By: Fabrizio Lombardozzi (fabrizio_lombardozzi) 2009-05-27 03:49:09

I've just tested in the same scenario Asterisk v.1.6.1.0 but the problem is still present.
By: Joshua C. Colp (jcolp) 2009-05-28 09:04:06

Okay. Please provide updated logs with just console output and sip debug.
By: Fabrizio Lombardozzi (fabrizio_lombardozzi) 2009-05-28 09:30:28

I just uploaded a new log with two cases, you can strip console (and comment) by:
cat full_1.6.1.0 |grep -i _realtime | less -r
By: Joshua C. Colp (jcolp) 2009-06-01 09:59:35

There is no actual sip debug in here, so I can't see the SIP packets that are causing this to happen.
By: Fabrizio Lombardozzi (fabrizio_lombardozzi) 2009-06-01 10:47:40

Just uploaded sip debug and console for a faulty event.
By: Joshua C. Colp (jcolp) 2009-06-01 12:57:31

After further research this issue has actually already been fixed. You can either wait for the next release or get 1.6.1 from SVN to receive the fix. The revision that fixed it, for reference, is 194507.