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:24 | Date Closed: | 2008-11-26 13:57:17.000-0600 |
Priority: | Minor | Regression? | No |
Status: | Closed/Complete | Components: | 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 |