[Home]

Summary:ASTERISK-12766: Channel re-invited on destination ringing not re-invited back if ringing abandoned.
Reporter:David Woolley (davidw)Labels:
Date Opened:2008-09-23 08:25:05Date Closed:2010-02-23 09:52:31.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) \\simple_mode_sip_channels_plus.txt
( 1) simple_mode_sip_channels_plus.txt
( 2) simple_model_full_trace.txt
Description:An incoming SIP call is answered by an agent and then AMI transferred to a PSTN line on Cisco CCM.  The Cisco provides SDP on the Ringing response and Asterisk re-invites the incoming call immediately it gets that response.

The Dial command times out and cancels the outgoing call, but at no time does the re-invite get undone, even when the dialplan eventually successfully returns the call to the agent.  The result is a silent call.

The un-re-invite can be forced by parking the call and then unparking it (in this case with an AMI Originate which queues it back to an agent).

This is a big problem for us as it is important for our application that as many calls as possible have their speech path removed from the Asterisk system.

I am also concerned that specifying multiple destinations in the Dial command, may not inhibit the re-invite, leading to conflicting re-invites, in the order of the Ringing events.  However, I haven't confirmed that this is the case.

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

The environment in which this is happening is quite complicated, and, unless a diagnosis is immediately evident, I will try and simplify the model.  In particular, it is possible that neither the use of queues nor of AMI is necessary.

In the mean time, this the SIP history for the outgoing call:

1. NewChan         Channel SIP/192.168.10.10-09d7a1c0 - from 3ad01dc53fedde7814a82
2. TxReqRel        INVITE / 102 INVITE - -UNKNOWN-
3. Rx              SIP/2.0 / 102 INVITE / 100 Trying
4. Rx              SIP/2.0 / 102 INVITE / 180 Ringing

Eventually times out, but I can't capture the cancel using history.

This is the SIP history for the incoming call (note timing correlations have been established using sip set debug):

1. Rx              INVITE / 102 INVITE / sip:1200@192.168.71.115
2. AuthChal        Auth challenge sent for  - nc 0
3. TxRespRel       SIP/2.0 / 102 INVITE - 407 Proxy Authentication Required
4. SchedDestroy    32000 ms
5. Rx              ACK / 102 ACK / sip:1200@192.168.71.115
6. Rx              INVITE / 103 INVITE / sip:1200@192.168.71.115
7. CancelDestroy
8. Invite          New call: 4b2735bc4168d2096c83bdbc0323a4d6@192.168.130.103
9. AuthOK          Auth challenge succesful for loadbot
10. NewChan         Channel SIP/loadbot-09dabfa0 - from 4b2735bc4168d2096c83bdbc032
11. TxResp          SIP/2.0 / 103 INVITE - 100 Trying
12. TxRespRel       SIP/2.0 / 103 INVITE - 200 OK
13. Rx              ACK / 103 ACK / sip:1200@192.168.71.115

Outgoing channel returns Ringing

14. ReInv           Re-invite sent
15. TxReqRel        INVITE / 102 INVITE - -UNKNOWN-
16. Rx              SIP/2.0 / 102 INVITE / 100 Trying
17. Rx              SIP/2.0 / 102 INVITE / 200 OK
18. TxReq           ACK / 102 ACK - -UNKNOWN-

Outgoing channel call cancelled by timeout

Call returned to agent; note re-invite hasn't been countermanded.

The following relates to AMI transferring to 700 then AMI originating back to an agent queue, from the parking lot, but I haven't checked whether the masquerade relates to the former or the latter.

19. Masq            Old channel: Parked/SIP/loadbot-09dabfa0<ZOMBIE>
20. Masq (cont)     ...new owner: SIP/loadbot-09dabfa0
21. ReInv           Re-invite sent
22. TxReqRel        INVITE / 103 INVITE - -UNKNOWN-
23. Rx              SIP/2.0 / 103 INVITE / 100 Trying
24. Rx              SIP/2.0 / 103 INVITE / 200 OK
25. TxReq           ACK / 103 ACK - -UNKNOWN-

Now have speech back.
Comments:By: David Woolley (davidw) 2008-09-23 10:10:52

The simplest model that seems to produce this effect is something like (phone number changed):

exten => 6183,1,Answer
exten => 6183,n,Dial(SIP/988888888888@192.168.10.10,10)
exten => 6183,n,Dial(Agent/3003,,t) ' flag to prevent re-invite out.

If one has a SIP phone directly, rather than the Agent as a fallback, the re-invite gets undone.  If one doesn't pre-answer, in that case, there are no re-invites and the PSTN call is connected with a local bridge, which may, itself be a problem, but we will always have answered.

With the fragment above, the SIP history, for the caller, is:

 * SIP Call
1. Rx              INVITE / 1 INVITE / sip:6183@192.168.130.116
2. AuthChal        Auth challenge sent for  - nc 0
3. TxRespRel       SIP/2.0 / 1 INVITE - 407 Proxy Authentication Required
4. SchedDestroy    32000 ms
5. Rx              ACK / 1 ACK / sip:6183@192.168.130.116
6. Rx              INVITE / 2 INVITE / sip:6183@192.168.130.116
7. CancelDestroy  
8. Invite          New call: OGI0ZGEzOTZmMTg4MjcwMzlhNTBkMTBmMDRhZGQzODY.
9. AuthOK          Auth challenge succesful for djw-messenger
10. NewChan         Channel SIP/djw-messenger-09f826a8 - from OGI0ZGEzOTZmMTg4MjcwM
11. TxResp          SIP/2.0 / 2 INVITE - 100 Trying
12. TxRespRel       SIP/2.0 / 2 INVITE - 200 OK
13. Rx              ACK / 2 ACK / sip:6183@192.168.130.116
14. ReInv           Re-invite sent
15. TxReqRel        INVITE / 102 INVITE - -UNKNOWN-
16. Rx              SIP/2.0 / 102 INVITE / 200 OK
17. TxReq           ACK / 102 ACK - -UNKNOWN-

and one ends up with the originator bridged thus:

 Audio IP:               192.168.10.10 (Outside bridge)

and the agent bridged thus:

 Audio IP:               192.168.130.116 (local)

I will attach the full SIP show channel's for this case.

Oops got two copies, as it produced an error about a bad tag and I thought the upload had failed :-(.


By: David Woolley (davidw) 2008-09-23 12:05:26

Another variation, which demonstrates that it is not the use of the Agent that triggers the fault, but rather the use of direct SIP destination that mitigates it:

exten => 6183,1,Answer
exten => 6183,n,Dial(SIP/988888888888@192.168.10.10,10)
exten => 6183,n,Read(variable,enter-ext-of-person,,,100)
exten => 6183,n,Noop(${variable})

 * SIP Call
1. Rx              INVITE / 1 INVITE / sip:6183@192.168.130.116
2. AuthChal        Auth challenge sent for  - nc 0
3. TxRespRel       SIP/2.0 / 1 INVITE - 407 Proxy Authentication Required
4. SchedDestroy    32000 ms
5. Rx              ACK / 1 ACK / sip:6183@192.168.130.116
6. Rx              INVITE / 2 INVITE / sip:6183@192.168.130.116
7. CancelDestroy  
8. Invite          New call: OWQ1NGQxMzczMDYyZTJhODNhYmRmMzI1YzNkZjg2OWQ.
9. AuthOK          Auth challenge succesful for djw-messenger
10. NewChan         Channel SIP/djw-messenger-09f66640 - from OWQ1NGQxMzczMDYyZT
JhO
11. TxResp          SIP/2.0 / 2 INVITE - 100 Trying
12. TxRespRel       SIP/2.0 / 2 INVITE - 200 OK
13. Rx              ACK / 2 ACK / sip:6183@192.168.130.116
14. ReInv           Re-invite sent
15. TxReqRel        INVITE / 102 INVITE - -UNKNOWN-
16. Rx              SIP/2.0 / 102 INVITE / 200 OK
17. TxReq           ACK / 102 ACK - -UNKNOWN-
   -- User entered nothing, 97 chances left
   -- <SIP/djw-messenger-09f66640> Playing 'enter-ext-of-person' (language 'en'
By: David Woolley (davidw) 2008-09-23 12:39:41

The problem doesn't happen if the call is actually answered (note, because it is PSTN, there is no reverse clear and the call has to be forced down from the dialplan):

exten => 6183,1,Answer
exten => 6183,n,Dial(SIP/988888888888@192.168.10.10,10,gS(5))
exten => 6183,n,Read(variable,enter-ext-of-person,,,100)
exten => 6183,n,Noop(${variable})

it also doesn't happen when there isn't an early SDP (although I think there were more re-invites than I expected!  The g is a hangover, this call was allowed to timeout ringing):

exten => 6183,1,Answer
exten => 6183,n,Dial(SIP/6906@192.168.10.10,10,g)
exten => 6183,n,Read(variable,enter-ext-of-person,,,100)
exten => 6183,n,Noop(${variable})
By: David Woolley (davidw) 2008-10-17 06:02:38

Re-verified on 1.6.0.
By: David Woolley (davidw) 2008-10-17 10:08:55

Using the 1.6.0 code, what I think is happening is that:

The native bridge is being trigged by this code, in apps/app_dial.c (or possible the proceeding or progress cases):

apps/app_dial.c
   703                                 case AST_CONTROL_RINGING:
   704                                         ast_verb(3, "%s is ringing\n", c->name);
   705                                         /* Setup early media if appropriate */
   706                                         if (single && CAN_EARLY_BRIDGE(peerflags, in, c))
   707                                                 ast_channel_early_bridge(in, c);

When the call fails, this gets run:

  1942         ast_channel_early_bridge(chan, NULL);

which, eventually, ends up in main/rtp.c.  Although that makes a pretence of handling a null second parameter, it eventually reaches this code:

  1857         if (audio_src_res == AST_RTP_TRY_NATIVE && srcpr->get_codec)
  1858                 srccodec = srcpr->get_codec(c1);
  1859         else
  1860                 srccodec = 0;
  1861         if (audio_dest_res == AST_RTP_TRY_NATIVE && destpr->get_codec)
  1862                 destcodec = destpr->get_codec(c0);
  1863         else
  1864                 destcodec = 0;

This is slightly weird in that c1 and c0 seem, to me, to be crossed over, but even without that, I presume the null c1 would result in, at least destcodec getting set to zero, which is a condition for exiting the routine.

What I presume was intended to happen, was that a null c1 should cause c0 to be re-invited back to Asterisk.

Have I missed anything here?
By: Leif Madsen (lmadsen) 2008-10-17 15:17:36

putnopvut I've assigned this to you in the hopes you may have some insight here. I know I've been piling on a lot of SIP bugs to you lately, so feel free to unassign anything from yourself if you're not able to really deal with it.

Thanks!
By: David Woolley (davidw) 2008-10-21 06:50:30

I tried disabling the early bridge on ringing, progress and proceeding, and, at least for the ringing, and subject to soaking, it seems to have removed the symptom without compromising external bridging on answer.

However, this is removing functionality, rather than really fixing it.

I suspect that things would still break if one allowed the dialplan to continue after answer and hangup.
By: Digium Subversion (svnbot) 2008-12-18 11:12:03.000-0600

Repository: asterisk
Revision: 165591

U   branches/1.4/main/rtp.c

------------------------------------------------------------------------
r165591 | file | 2008-12-18 11:12:03 -0600 (Thu, 18 Dec 2008) | 4 lines

Only care about a compatible codec for early bridging if we are actually bridging to another channel. If we are not we actually want to bring the audio back to us.
(closes issue ASTERISK-12766)
Reported by: davidw

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=165591
By: Digium Subversion (svnbot) 2008-12-18 11:13:33.000-0600

Repository: asterisk
Revision: 165599

_U  trunk/
U   trunk/main/rtp.c

------------------------------------------------------------------------
r165599 | file | 2008-12-18 11:13:33 -0600 (Thu, 18 Dec 2008) | 11 lines

Merged revisions 165591 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r165591 | file | 2008-12-18 13:11:42 -0400 (Thu, 18 Dec 2008) | 4 lines
 
 Only care about a compatible codec for early bridging if we are actually bridging to another channel. If we are not we actually want to bring the audio back to us.
 (closes issue ASTERISK-12766)
 Reported by: davidw
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=165599
By: Digium Subversion (svnbot) 2008-12-18 11:14:24.000-0600

Repository: asterisk
Revision: 165603

_U  branches/1.6.0/
U   branches/1.6.0/main/rtp.c

------------------------------------------------------------------------
r165603 | file | 2008-12-18 11:14:24 -0600 (Thu, 18 Dec 2008) | 18 lines

Merged revisions 165599 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r165599 | file | 2008-12-18 13:13:32 -0400 (Thu, 18 Dec 2008) | 11 lines
 
 Merged revisions 165591 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r165591 | file | 2008-12-18 13:11:42 -0400 (Thu, 18 Dec 2008) | 4 lines
   
   Only care about a compatible codec for early bridging if we are actually bridging to another channel. If we are not we actually want to bring the audio back to us.
   (closes issue ASTERISK-12766)
   Reported by: davidw
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=165603
By: Digium Subversion (svnbot) 2008-12-18 11:15:51.000-0600

Repository: asterisk
Revision: 165605

_U  branches/1.6.1/
U   branches/1.6.1/main/rtp.c

------------------------------------------------------------------------
r165605 | file | 2008-12-18 11:15:51 -0600 (Thu, 18 Dec 2008) | 18 lines

Merged revisions 165599 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r165599 | file | 2008-12-18 13:13:32 -0400 (Thu, 18 Dec 2008) | 11 lines
 
 Merged revisions 165591 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r165591 | file | 2008-12-18 13:11:42 -0400 (Thu, 18 Dec 2008) | 4 lines
   
   Only care about a compatible codec for early bridging if we are actually bridging to another channel. If we are not we actually want to bring the audio back to us.
   (closes issue ASTERISK-12766)
   Reported by: davidw
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=165605
By: Leif Madsen (lmadsen) 2009-04-21 21:22:33

Reopening issue per reporter in a note in issue 14945.
By: Leif Madsen (lmadsen) 2009-04-21 21:22:57

davidw: what part of this issue is not resolved?
By: David Woolley (davidw) 2009-04-22 05:35:27

The basic symptom is still there. If you run the scenario in comment 92796, the re-invite back doesn't get done.  It's a few weeks since I reverified this, so I'll need to run it again to get a trace.

I think, in trying to work out what was going wrong, I found another problem, and that is what has got fixed.
By: David Woolley (davidw) 2009-04-22 06:27:17

Specifically, on a clean 1.6.0.6, the 92796 scenario results in sip show channel on the caller showing:

 Audio IP:               192.168.10.10 (Outside bridge)

when it should have been re-invited back to the internal, Read, service.
By: Digium Subversion (svnbot) 2009-05-19 09:41:46

Repository: asterisk
Revision: 195448

U   branches/1.4/channels/chan_sip.c

------------------------------------------------------------------------
r195448 | file | 2009-05-19 09:41:46 -0500 (Tue, 19 May 2009) | 7 lines

Fix a bug where direct RTP setup would partially occur even when disabled if the calling channel was answered.

(issue ASTERISK-12766)
Reported by: davidw
(issue ASTERISK-13370)
Reported by: mbnwa

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=195448
By: Digium Subversion (svnbot) 2009-05-19 09:43:55

Repository: asterisk
Revision: 195449

_U  trunk/
U   trunk/channels/chan_sip.c

------------------------------------------------------------------------
r195449 | file | 2009-05-19 09:43:55 -0500 (Tue, 19 May 2009) | 14 lines

Merged revisions 195448 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r195448 | file | 2009-05-19 11:41:45 -0300 (Tue, 19 May 2009) | 7 lines
 
 Fix a bug where direct RTP setup would partially occur even when disabled if the calling channel was answered.
 
 (issue ASTERISK-12766)
 Reported by: davidw
 (issue ASTERISK-13370)
 Reported by: mbnwa
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=195449
By: Digium Subversion (svnbot) 2009-05-19 09:45:55

Repository: asterisk
Revision: 195450

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_sip.c

------------------------------------------------------------------------
r195450 | file | 2009-05-19 09:45:55 -0500 (Tue, 19 May 2009) | 21 lines

Merged revisions 195449 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r195449 | file | 2009-05-19 11:43:54 -0300 (Tue, 19 May 2009) | 14 lines
 
 Merged revisions 195448 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r195448 | file | 2009-05-19 11:41:45 -0300 (Tue, 19 May 2009) | 7 lines
   
   Fix a bug where direct RTP setup would partially occur even when disabled if the calling channel was answered.
   
   (issue ASTERISK-12766)
   Reported by: davidw
   (issue ASTERISK-13370)
   Reported by: mbnwa
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=195450
By: Digium Subversion (svnbot) 2009-05-19 09:47:47

Repository: asterisk
Revision: 195451

_U  branches/1.6.1/
U   branches/1.6.1/channels/chan_sip.c

------------------------------------------------------------------------
r195451 | file | 2009-05-19 09:47:47 -0500 (Tue, 19 May 2009) | 21 lines

Merged revisions 195449 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r195449 | file | 2009-05-19 11:43:54 -0300 (Tue, 19 May 2009) | 14 lines
 
 Merged revisions 195448 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r195448 | file | 2009-05-19 11:41:45 -0300 (Tue, 19 May 2009) | 7 lines
   
   Fix a bug where direct RTP setup would partially occur even when disabled if the calling channel was answered.
   
   (issue ASTERISK-12766)
   Reported by: davidw
   (issue ASTERISK-13370)
   Reported by: mbnwa
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=195451
By: Digium Subversion (svnbot) 2009-05-19 09:49:40

Repository: asterisk
Revision: 195452

_U  branches/1.6.2/
U   branches/1.6.2/channels/chan_sip.c

------------------------------------------------------------------------
r195452 | file | 2009-05-19 09:49:40 -0500 (Tue, 19 May 2009) | 21 lines

Merged revisions 195449 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r195449 | file | 2009-05-19 11:43:54 -0300 (Tue, 19 May 2009) | 14 lines
 
 Merged revisions 195448 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r195448 | file | 2009-05-19 11:41:45 -0300 (Tue, 19 May 2009) | 7 lines
   
   Fix a bug where direct RTP setup would partially occur even when disabled if the calling channel was answered.
   
   (issue ASTERISK-12766)
   Reported by: davidw
   (issue ASTERISK-13370)
   Reported by: mbnwa
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=195452
By: Joshua C. Colp (jcolp) 2009-05-19 10:51:04

After further examination of the log files I believe my directrtpsetup change fixed this. While this option may have been disabled it was still being done on part of the leg, causing things to go weird. The change I made now ensures directrtpsetup is indeed disabled if configured as such.