[Home]

Summary:ASTERISK-12950: 302 Redirect (forward no answer) to bad extension causes channel to be left up (Ringing)
Reporter:David Woolley (davidw)Labels:
Date Opened:2008-10-22 10:35:24Date Closed:2008-11-26 13:57:17.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_dial
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 13764_v2.patch
( 1) 13764.patch
Description:When testing something, we accidentally used a phone that had been configured to call forward no-answer to a bad extension.  It took us a while to realise, so we made several calls.  Subsequent core/sip show channels show that all of these attempts are still ringing on the attempted correct number, even though the SIP ones show the ACK to the 302 as the last thing sent.

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

This is minor for us, as having a phone re-direct no answer is not significant for our application.

Although this is in terms of SIP protocol, I believe the real problem lies in do_forward in app_dial; particularly noting the header comments:

* XXX this code is highly suspicious, as it essentially overwrites
* the outgoing channel without properly deleting it.

This is the console trace starting from the ack to the 302 (one context and one name obfuscated):

CSeq: 102 ACK
User-Agent: Asterisk PBX 1.6.0
Content-Length: 0


---
[2008-10-22 13:30:31.941] VERBOSE[10555] logger.c:     -- Now forwarding Local/*6185@default-a926;2 to 'Local/4000@XXXXXXXXXXXXXXXX' (thanks to SIP/4222-088be0f
0)
[2008-10-22 13:30:31.941] NOTICE[10555] chan_local.c: No such extension/context 4000@XXXXXXXXXXXXXXXX creating local channel
[2008-10-22 13:30:31.941] NOTICE[10555] app_dial.c: Unable to create local channel for call forward to 'Local/4000@XXXXXXXXXXXXXXXX' (cause = 0)
[2008-10-22 13:30:31.941] VERBOSE[10555] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[2008-10-22 13:30:31.941] VERBOSE[10555] logger.c:     -- Auto fallthrough, channel 'Local/*6185@default-a926;2' status is 'CHANUNAVAIL'
[2008-10-22 13:30:31.941] VERBOSE[10557] logger.c: Scheduling destruction of SIP dialog '8361137f-9aba52c0-ff522731@192.168.1.3' in 32000 ms (Method: ACK)
[2008-10-22 13:30:31.941] VERBOSE[10557] logger.c: set_destination: Parsing <sip:4222@192.168.81.154:1024> for address/port to send to
[2008-10-22 13:30:31.942] VERBOSE[10557] logger.c: set_destination: set destination to 192.168.81.154, port 1024
[2008-10-22 13:30:31.942] VERBOSE[10557] logger.c: Reliably Transmitting (no NAT) to 192.168.81.154:1024:
BYE sip:4222@192.168.81.154:1024 SIP/2.0
Via: SIP/2.0/UDP 192.168.130.140:5060;branch=z9hG4bK4c61da01;rport
Max-Forwards: 70
From: <sip:700@192.168.130.140;user=phone>;tag=as441a1dab
To: "YYYY" <sip:4222@192.168.130.140>;tag=83D839D2-E7CCE3A3
Call-ID: 8361137f-9aba52c0-ff522731@192.168.1.3
CSeq: 102 BYE
User-Agent: Asterisk PBX 1.6.0
Content-Length: 0


---
[2008-10-22 13:30:31.942] VERBOSE[10557] logger.c:   == Spawn extension (parkedcalls, 701, 1) exited non-zero on 'Local/*6185@default-a926;1'
[2008-10-22 13:30:32.032] VERBOSE[7792] logger.c:
<--- SIP read from UDP://192.168.81.154:1024 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.130.140:5060;branch=z9hG4bK4c61da01;rport
From: <sip:700@192.168.130.140;user=phone>;tag=as441a1dab
To: "YYYY" <sip:4222@192.168.130.140>;tag=83D839D2-E7CCE3A3
CSeq: 102 BYE
Call-ID: 8361137f-9aba52c0-ff522731@192.168.1.3
Contact: <sip:4222@192.168.81.154:1024>
User-Agent: PolycomSoundPointIP-SPIP_320-UA/2.2.2.0084
Content-Length: 0


<------------->
[2008-10-22 13:30:32.032] VERBOSE[7792] logger.c: --- (9 headers 0 lines) ---
[2008-10-22 13:30:32.032] VERBOSE[7792] logger.c: SIP Response message for INCOM
ING dialog BYE arrived
[2008-10-22 13:30:32.032] VERBOSE[7792] logger.c: Really destroying SIP dialog '
8361137f-9aba52c0-ff522731@192.168.1.3' Method: ACK

Unfortunately, we restarted as part of the intended test and removed the redirect from the phone, so I can't easily get the show channels output.
Comments:By: Leif Madsen (lmadsen) 2008-11-24 13:38:22.000-0600

I didn't really want to change this to 'assigned', but did want to assign this (does that make sense?! :))

Assigned to putnopvut for now because I believe he may be the best person to determine how to move this issue forward. Please reassign as necessary.

Thanks!
By: Mark Michelson (mmichelson) 2008-11-25 15:33:35.000-0600

It appears that the problem is that the Local channel is requested in the do_forward function, but then it is not properly hung up if the subsequent ast_call fails. The one-liner I uploaded (13764.patch) takes care of the problem in my test setup. Please test and report if it fixes the problem for you as well.
By: David Woolley (davidw) 2008-11-26 09:21:57.000-0600

Still the same problem.

centos*CLI> core show channels
Channel              Location             State   Application(Data)            
SIP/6106-085d3b28    6106@internal:1      Ringing AppDial((Outgoing Line))      
1 active channel
0 active calls
1 call processed
[2008-11-26 14:59:11.163] NOTICE[392]: chan_sip.c:18078 handle_request_subscribe
: Received SIP subscribe for peer without mailbox: djw-messenger
centos*CLI> sip show channels
Peer             User/ANR    Call ID          Format           Hold     Last Mes
sage  
192.168.81.160   6106        47ed6fbd3a871a0  0x4 (ulaw)       No       Tx: ACK
                 
1 active SIP dialog

History from a second run:

centos*CLI>
 * SIP Call
1. NewChan         Channel SIP/6106-085dba90 - from 421f7355177bd2ec60ab08e10c16
8e
2. TxReqRel        INVITE / 102 INVITE - -UNKNOWN-
3. Rx              SIP/2.0 / 102 INVITE / 100 Trying
4. Rx              SIP/2.0 / 102 INVITE / 180 Ringing
5. Rx              SIP/2.0 / 102 INVITE / 302 Moved Temporarily
6. TxReq           ACK / 102 ACK - -UNKNOWN-


We are getting:

app_dial.c: Unable to create local channel for call forward

not the

Failed to dial on local channel for call forward to '%s'\n

we would get if the patched code were executed.

Looking at this fragment, c's nullness doesn't seem to change between the two ifs, and your patch is in the else at the end, so the message we get is incompatible with going down the branch with the patch.

to 'Local/6199@internal' (cause = 0)
   499                 if (c) {
   500                         if (single)
   501                                 ast_channel_make_compatible(o->chan, in)
   501 ;
   502                         ast_channel_inherit_variables(in, o->chan);
   503                         ast_channel_datastore_inherit(in, o->chan);
   504                 } else
   505                         ast_log(LOG_NOTICE, "Unable to create local chan
   505 nel for call forward to '%s/%s' (cause = %d)\n", tech, stuff, cause);
   506         }
   507         if (!c) {
   508                 ast_clear_flag64(o, DIAL_STILLGOING);
   509                 handle_cause(cause, num);
   510         } else {
By: Mark Michelson (mmichelson) 2008-11-26 09:32:53.000-0600

Ah I see. I pretty much solved the opposite problem that you have. In my case, the Local channel was being created properly, but ast_call was failing. In that case, the original destination was hung up, but not the newly created Local channel.

It seems that now the problem is that if the Local channel is not created properly, then the original destination is not hung up properly. I'm going to take a look at chan_local.c to see if I can spot an easy way to make local_request fail so that I can get my test case correct.
By: Mark Michelson (mmichelson) 2008-11-26 09:41:55.000-0600

This will teach me not to test in trunk when a bug is reported against 1.6.0. In 1.6.0, an invalid extension causes ast_request to fail when trying to create a local channel. In trunk, however, the ast_request succeeds. I should have a patch available shortly.
By: Mark Michelson (mmichelson) 2008-11-26 10:05:04.000-0600

Version 2 of the patch is uploaded now. In addition to the change made for the first patch, there is now an extra directive to hang up the original destination channel in the case that ast_request fails when attempting to create the local channel.
By: David Woolley (davidw) 2008-11-26 10:50:53.000-0600

Looks OK now, although I only know how to push it down the branch that was causing our problem.

I tried with the redirect valid and answered, and note that almost no PBX data appeared in the final outgoing channel (optimised out local channel) - normally you get a pseudo application for the other side of a bridge.  I don't know if this is considered a problem:

--   PBX   --
       Context: internal
     Extension:
      Priority: 1
    Call Group: 0
  Pickup Group: 0
   Application: (N/A)
          Data: (None)
   Blocking in: ast_waitfor_nandfds
     Variables:


By: Mark Michelson (mmichelson) 2008-11-26 11:22:54.000-0600

Whether it's a problem or not is pretty much up to whoever is using the application :) I took a look and this behavior is not new. The application and data for the final channel in a call forward situation has been like this for a while (i.e. 1.4 behaves like this too).

If you think this is problematic, feel free to open a new bug. This new problem is outside the scope of this issue, though, so I won't pursue fixing it here. Given that things appear ok on this issue, I'm going to commit my fixes and close this.
By: Digium Subversion (svnbot) 2008-11-26 13:57:16.000-0600

Repository: asterisk
Revision: 159554

U   trunk/apps/app_dial.c

------------------------------------------------------------------------
r159554 | mmichelson | 2008-11-26 13:57:16 -0600 (Wed, 26 Nov 2008) | 19 lines

Add some necessary hangup commands in the case that forwarding
a call fails

1) Hang up the original destination if the local channel cannot
  be requested.
2) Hang up the local channel (in addition to the original destination)
  if ast_call fails when calling the newly created local channel.

This prevents channels from sticking around forever in the
case of a botched call forward (e.g. to an extension which does not
exist).

(closes issue ASTERISK-12950)
Reported by: davidw
Patches:
     13764_v2.patch uploaded by putnopvut (license 60)
Tested by: putnopvut, davidw


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

http://svn.digium.com/view/asterisk?view=rev&revision=159554