[Home]

Summary:ASTERISK-13463: Transfer executes callers channel in wrong context
Reporter:alesz (alesz)Labels:
Date Opened:2009-01-27 06:58:05.000-0600Date Closed:2009-02-03 07:51:12.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Transfers
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) consecutive-transfer.txt
Description:hen call is transfered using blind or attended transfer using dtmf code defined in features.conf or using phone transfer (tested on GXP2000 and polycom 330) it appears callers channel goes to same context as callee's last context instead of continuing on typed in extension in context defined by TRANSFER_CONTEXT global variable.
Callee-s channel hangups ok.

Using Asterisk 1.6.0.5 & Freepbx 2.5.1.1. This started happening somewhere around 1.6.0.3-rc1.

workaround: manually send call to correct context using goto. does not work with consecutive transfers: first > second > third


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

Tested on two different servers.

- Call an extensions
- Transfer call to other extension
- both legs execute hangup

example bellow is call over ITSP to extension 60 which transfers to 65:

   -- Executing [s@from-itsp:1] Set("SIP/012481632-b6326038", "TO=<sip:012481632@10.22.11.20;user=phone>") in new stack
   -- Executing [s@from-itsp:2] Set("SIP/012481632-b6326038", "CALLERID(all)="Call" <0040556982>") in new stack
   -- Executing [s@from-itsp:3] Goto("SIP/012481632-b6326038", "60,1") in new stack
   -- Goto (from-itsp,60,1)
   -- Executing [60@from-itsp:1] Goto("SIP/012481632-b6326038", "from-internal,60,1") in new stack
   -- Goto (from-internal,60,1)
   -- Executing [60@from-internal:1] Macro("SIP/012481632-b6326038", "exten-vm,novm,60") in new stack
   -- Executing [s@macro-exten-vm:1] Macro("SIP/012481632-b6326038", "user-callerid") in new stack
   -- Executing [s@macro-user-callerid:1] Set("SIP/012481632-b6326038", "AMPUSER=0040556982") in new stack
   -- Executing [s@macro-user-callerid:2] GotoIf("SIP/012481632-b6326038", "0?report") in new stack
   -- Executing [s@macro-user-callerid:3] ExecIf("SIP/012481632-b6326038", "1?Set(REALCALLERIDNUM=0040556982)") in new stack
   -- Executing [s@macro-user-callerid:4] Set("SIP/012481632-b6326038", "AMPUSER=") in new stack
   -- Executing [s@macro-user-callerid:5] Set("SIP/012481632-b6326038", "AMPUSERCIDNAME=") in new stack
   -- Executing [s@macro-user-callerid:6] GotoIf("SIP/012481632-b6326038", "1?report") in new stack
   -- Goto (macro-user-callerid,s,10)
   -- Executing [s@macro-user-callerid:10] GotoIf("SIP/012481632-b6326038", "0?continue") in new stack
   -- Executing [s@macro-user-callerid:11] Set("SIP/012481632-b6326038", "__TTL=64") in new stack
   -- Executing [s@macro-user-callerid:12] GotoIf("SIP/012481632-b6326038", "1?continue") in new stack
   -- Goto (macro-user-callerid,s,19)
   -- Executing [s@macro-user-callerid:19] NoOp("SIP/012481632-b6326038", "Using CallerID "Call" <0040556982>") in new stack
   -- Executing [s@macro-exten-vm:2] Set("SIP/012481632-b6326038", "RingGroupMethod=none") in new stack
   -- Executing [s@macro-exten-vm:3] Set("SIP/012481632-b6326038", "VMBOX=novm") in new stack
   -- Executing [s@macro-exten-vm:4] Set("SIP/012481632-b6326038", "EXTTOCALL=60") in new stack
   -- Executing [s@macro-exten-vm:5] Set("SIP/012481632-b6326038", "CFUEXT=") in new stack
   -- Executing [s@macro-exten-vm:6] Set("SIP/012481632-b6326038", "CFBEXT=") in new stack
   -- Executing [s@macro-exten-vm:7] Set("SIP/012481632-b6326038", "RT=""") in new stack
   -- Executing [s@macro-exten-vm:8] Macro("SIP/012481632-b6326038", "record-enable,60,IN") in new stack
   -- Executing [s@macro-record-enable:1] GotoIf("SIP/012481632-b6326038", "1?check") in new stack
   -- Goto (macro-record-enable,s,4)
   -- Executing [s@macro-record-enable:4] AGI("SIP/012481632-b6326038", "recordingcheck,20090127-134045,1233060045.195") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
recordingcheck,20090127-134045,1233060045.195: Inbound recording enabled.
recordingcheck,20090127-134045,1233060045.195: CALLFILENAME=20090127-134045-1233060045.195
   -- <SIP/012481632-b6326038>AGI Script recordingcheck completed, returning 0
   -- Executing [s@macro-record-enable:999] MixMonitor("SIP/012481632-b6326038", "20090127-134045-1233060045.195.wav,,") in new stack
   -- Executing [s@macro-exten-vm:9] Macro("SIP/012481632-b6326038", "dial,,tTr,60") in new stack
   -- Executing [s@macro-dial:1] GotoIf("SIP/012481632-b6326038", "1?dial") in new stack
   -- Goto (macro-dial,s,3)
   -- Executing [s@macro-dial:3] AGI("SIP/012481632-b6326038", "dialparties.agi") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
 == Begin MixMonitor Recording SIP/012481632-b6326038
dialparties.agi: Starting New Dialparties.agi
 == Manager 'admin' logged on from 127.0.0.1
dialparties.agi: Caller ID name is 'Call' number is '0040556982'
dialparties.agi: Methodology of ring is  'none'
   -- dialparties.agi: Added extension 60 to extension map
   -- dialparties.agi: Extension 60 cf is disabled
   -- dialparties.agi: Extension 60 do not disturb is disabled
   -- dialparties.agi: dbset CALLTRACE/60 to 0040556982
   -- dialparties.agi: Filtered ARG3: 60
 == Manager 'admin' logged off from 127.0.0.1
   -- <SIP/012481632-b6326038>AGI Script dialparties.agi completed, returning 0
   -- Executing [s@macro-dial:7] Dial("SIP/012481632-b6326038", "SIP/60,,tTr") in new stack
 == Using SIP RTP CoS mark 5
 == Using UDPTL CoS mark 5
   -- Called 60
   -- SIP/60-083258d8 is ringing
   -- SIP/60-083258d8 answered SIP/012481632-b6326038
   -- Started music on hold, class 'default', on SIP/012481632-b6326038
   -- Stopped music on hold on SIP/012481632-b6326038
   -- Executing [h@from-internal-xfer:1] Macro("SIP/012481632-b6326038", "hangupcall") in new stack
   -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/012481632-b6326038", "w") in new stack
   -- Executing [s@macro-hangupcall:2] NoCDR("SIP/012481632-b6326038", "") in new stack
   -- Executing [s@macro-hangupcall:3] GotoIf("SIP/012481632-b6326038", "1?skiprg") in new stack
   -- Goto (macro-hangupcall,s,6)
   -- Executing [s@macro-hangupcall:6] GotoIf("SIP/012481632-b6326038", "1?skipblkvm") in new stack
   -- Goto (macro-hangupcall,s,9)
   -- Executing [s@macro-hangupcall:9] GotoIf("SIP/012481632-b6326038", "1?theend") in new stack
   -- Goto (macro-hangupcall,s,11)
   -- Executing [s@macro-hangupcall:11] Hangup("SIP/012481632-b6326038", "") in new stack
 == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/012481632-b6326038' in macro 'hangupcall'
 == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/012481632-b6326038'
 == Spawn extension (macro-hangupcall, 65, 1) exited non-zero on 'SIP/012481632-b6326038' in macro 'dial'
 == Spawn extension (macro-hangupcall, 65, 1) exited non-zero on 'SIP/012481632-b6326038' in macro 'exten-vm'
 == Spawn extension (macro-hangupcall, 65, 1) exited non-zero on 'SIP/012481632-b6326038'
 == End MixMonitor Recording SIP/012481632-b6326038
Comments:By: alesz (alesz) 2009-01-27 07:05:44.000-0600

Attached dialplan execution when workaround using goto is used.
call goes: outside call > 65 > 64 > 71. Call drops on transfer to 71.
By: Leif Madsen (lmadsen) 2009-01-28 15:09:15.000-0600

Assigned to otherwiseguy to determine if this has anything to do with any of the recent changes he has been doing.

If not, then please re-assign to putnopvut. Thanks!
By: alesz (alesz) 2009-01-29 02:10:53.000-0600

Tested this issue with 1.6.1 (beta4 & trunk 167125) branch, works ok.
By: Terry Wilson (twilson) 2009-01-29 11:40:35.000-0600

I have tried with:

[globals]
TRNASFER_CONTEXT=transfers

[default]
include => parkedcalls
exten => _600X,1,NoOp(Testing)
exten => _600X,n,Dial(SIP/${EXTEN},,tTk)
exten => _600X,n,Hangup

[transfers]
exten => _600X,1,Answer
exten => _600X,n,Playback(vm-goodbye)
exten => _600X,n,Hangup


In the 1.6.0 branch (r172317) and ever scenario for me goes to [transfers] on a transfer, except SIP attended transfer.  Whether caller or callee does the transfer on builtin-blind, builtin-attended, or SIP blind, TRANSFER_CONTEXT seemed to be honored.  Can you verify this alesz?  A SIP attended transfer wouldn't be able to honor this because the consultative call is just like any other new call, so there would be no way to determine that it was part of a transfer.
By: alesz (alesz) 2009-01-30 02:45:50.000-0600

Thanks for testing. I tried this on 1.6.0.3 and it works the same way as yours. Then I dug a little deeper and found the issue I think is responsible for this behavior. Try to add h extension in transfer context like:

[transfer]
exten => h,1,Playback(hello-world)
exten => _600X,1,Answer
exten => _600X,n,Playback(vm-goodbye)
exten => _600X,n,Hangup

when I make a blind transfer, caller first hears hello-world and then goodbye. I am not sure if this is expected behavior?

Call trace:
-- SIP/13-08441000 answered SIP/338607316-b7614218
-- Started music on hold, class 'default', on SIP/338607316-b7614218
-- <SIP/13-08441000> Playing 'pbx-transfer.gsm' (language 'en')
-- Stopped music on hold on SIP/338607316-b7614218
-- Executing [h@transfers:1] Playback("SIP/338607316-b7614218", "hello-world") in new stack
-- <SIP/338607316-b7614218> Playing 'hello-world.gsm' (language 'en')
-- Executing [6000@transfers:1] Answer("SIP/338607316-b7614218", "") in new stack
-- Executing [6000@transfers:2] Playback("SIP/338607316-b7614218", "vm-goodbye") in new stack
-- <SIP/338607316-b7614218> Playing 'vm-goodbye.gsm' (language 'en')
-- Executing [6000@transfers:3] Hangup("SIP/338607316-b7614218", "") in new stack
Spawn extension (transfers, 6000, 3) exited non-zero on 'SIP/338607316-b7614218'
By: Mark Michelson (mmichelson) 2009-01-30 15:59:57.000-0600

Hi alesz,

I just set up your test on my machine, and using 1.6.0.3, and in all my test cases, the transferee heard "goodbye" and then was hung up. "hello world" did not play until after the Hangup app was run. There were four scenarios I tested. All calls were SIP-to-SIP with party A calling party B.

1. A uses DTMF code to blind transfer party B to 6000@transfer.
2. A uses button on SIP phone to blind transfer party B to 6000@transfer.
3. B uses DTMF code to blind transfer party A to 6000@transfer.
4. B uses button on SIP phone to blind transfer party A to 6000@transfer.

I'll try complicating the dialplan a bit to see if I can figure out what's up.
By: Mark Michelson (mmichelson) 2009-01-30 16:04:36.000-0600

Got it!

In order to make the problem occur, I had to call Dial from inside a macro, and party B had to be the one to transfer party A. I have now reproduced the behavior.

Now to see about fixing it. I need to check with murf to see if this is covered by anything that he has been working on recently.
By: Mark Michelson (mmichelson) 2009-01-30 16:30:13.000-0600

I talked to murf, and it appears that he has made a fix for something remarkably similar to this, and has applied the change to the 1.6.0 branch of Asterisk already. I'm going to run a test on the 1.6.0 branch to see if I still can reproduce the problem there.
By: Mark Michelson (mmichelson) 2009-01-30 16:44:12.000-0600

I re-ran my test using a fresh checkout of the 1.6.0 branch and found that the problem is gone, now. For sanity's sake, I reverted back to 1.6.0.3 and once again experienced the problem.

If possible, could you attempt to re-run your scenario with the 1.6.0 branch from subversion? I'd like confirmation that this issue has really been fixed and won't continue to fail with a more complicated dialplan in use.
By: Mark Michelson (mmichelson) 2009-01-30 17:38:37.000-0600

Oops, I apparently forgot to actually assign this to myself earlier when I started fixing it.
By: alesz (alesz) 2009-02-02 03:15:03.000-0600

Hi putnopvut,

Per your instructions I checked out 1.6.0 branch (r172813). Transfer now goes to the right context, but every dial to the SIP peer now returns 603 Declined. I need to look further in it but I have limited testing time, since it is a production machine.

Dialplan trace call 13 > 12:
   -- Executing [12@from-internal:1] Macro("SIP/13-08210ce0", "exten-vm,novm,12") in new stack
   -- Executing [s@macro-exten-vm:1] Macro("SIP/13-08210ce0", "user-callerid") in new stack
   -- Executing [s@macro-user-callerid:1] Set("SIP/13-08210ce0", "AMPUSER=13") in new stack
   -- Executing [s@macro-user-callerid:2] GotoIf("SIP/13-08210ce0", "0?report") in new stack
   -- Executing [s@macro-user-callerid:3] ExecIf("SIP/13-08210ce0", "1?Set(REALCALLERIDNUM=13)") in new stack
   -- Executing [s@macro-user-callerid:4] Set("SIP/13-08210ce0", "AMPUSER=13") in new stack
   -- Executing [s@macro-user-callerid:5] Set("SIP/13-08210ce0", "AMPUSERCIDNAME=Alesz") in new stack
   -- Executing [s@macro-user-callerid:6] GotoIf("SIP/13-08210ce0", "0?report") in new stack
   -- Executing [s@macro-user-callerid:7] Set("SIP/13-08210ce0", "AMPUSERCID=13") in new stack
   -- Executing [s@macro-user-callerid:8] Set("SIP/13-08210ce0", "CALLERID(all)="Alesz" <13>") in new stack
   -- Executing [s@macro-user-callerid:9] Set("SIP/13-08210ce0", "REALCALLERIDNUM=13") in new stack
   -- Executing [s@macro-user-callerid:10] GotoIf("SIP/13-08210ce0", "0?continue") in new stack
   -- Executing [s@macro-user-callerid:11] Set("SIP/13-08210ce0", "__TTL=64") in new stack
   -- Executing [s@macro-user-callerid:12] GotoIf("SIP/13-08210ce0", "1?continue") in new stack
   -- Goto (macro-user-callerid,s,19)
   -- Executing [s@macro-user-callerid:19] NoOp("SIP/13-08210ce0", "Using CallerID "Alesz" <13>") in new stack
   -- Executing [s@macro-exten-vm:2] Set("SIP/13-08210ce0", "RingGroupMethod=none") in new stack
   -- Executing [s@macro-exten-vm:3] Set("SIP/13-08210ce0", "VMBOX=novm") in new stack
   -- Executing [s@macro-exten-vm:4] Set("SIP/13-08210ce0", "EXTTOCALL=12") in new stack
   -- Executing [s@macro-exten-vm:5] Set("SIP/13-08210ce0", "CFUEXT=") in new stack
   -- Executing [s@macro-exten-vm:6] Set("SIP/13-08210ce0", "CFBEXT=") in new stack
   -- Executing [s@macro-exten-vm:7] Set("SIP/13-08210ce0", "RT=""") in new stack
   -- Executing [s@macro-exten-vm:8] Macro("SIP/13-08210ce0", "record-enable,12,IN") in new stack
   -- Executing [s@macro-record-enable:1] GotoIf("SIP/13-08210ce0", "1?check") in new stack
   -- Goto (macro-record-enable,s,4)
 == Spawn extension (macro-record-enable, s, 4) exited non-zero on 'SIP/13-08210ce0' in macro 'record-enable'
 == Spawn extension (macro-exten-vm, s, 8) exited non-zero on 'SIP/13-08210ce0' in macro 'exten-vm'
 == Spawn extension (from-internal, 12, 1) exited non-zero on 'SIP/13-08210ce0'
   -- Executing [h@from-internal:1] Macro("SIP/13-08210ce0", "hangupcall") in new stack
   -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/13-08210ce0", "w") in new stack
   -- Executing [s@macro-hangupcall:2] NoCDR("SIP/13-08210ce0", "") in new stack
   -- Executing [s@macro-hangupcall:3] GotoIf("SIP/13-08210ce0", "1?skiprg") in new stack
   -- Goto (macro-hangupcall,s,6)
   -- Executing [s@macro-hangupcall:6] GotoIf("SIP/13-08210ce0", "1?skipblkvm") in new stack
   -- Goto (macro-hangupcall,s,9)
   -- Executing [s@macro-hangupcall:9] GotoIf("SIP/13-08210ce0", "1?theend") in new stack
   -- Goto (macro-hangupcall,s,11)
   -- Executing [s@macro-hangupcall:11] Hangup("SIP/13-08210ce0", "") in new stack
 == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/13-08210ce0' in macro 'hangupcall'
 == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/13-08210ce0'
By: Mark Michelson (mmichelson) 2009-02-02 09:46:17.000-0600

Getting a 603 back from the SIP peer on every call is definitely problematic and needs to be dealt with, but it also is a completely separate issue than the originally-reported one here.

Let's try to separate these out a little bit to keep things more manageable. Could you please open a new bug report about this. On that issue, it would be helpful to see SIP debug from a failed call, and it may potentially be helpful to see sip.conf entries for the involved parties.

Also, since you stated that calls are being transferred to the correct context in your latest note, would you be comfortable if I closed this issue out as being fixed?
By: alesz (alesz) 2009-02-03 02:02:49.000-0600

Ok, I tested it again (r173111), still getting 603, but transfer context seems to be ok now. I agree, that you can close this issue and if the new error (it was just an observation, not meant as a report) won't go away in a couple of revisions, I'll post another bug report with full sip debug.
Thank you for your time and effort.
By: Leif Madsen (lmadsen) 2009-02-03 07:51:12.000-0600

Closing this issue as it appears to be fixed now.

alesz, please open a separate issue for the 603 part you described. Thanks!