Asterisk starting blind transfer, destination rings, asterisk cancels & call is lost

dkmortensen · January 23, 2012, 9:19pm

Hello all,

I have a system running AsteriskNOW with asterisk asterisk-1.8.8.2-1_centos5 from AsteriskNOW repository. I just changed our Polycom 335 sip.conf so that blindpreferred=1 (all transfers default as blind transfers). If a customer calls in & we answer & transfer, everything works fine. But if we call out to a customer & then transfer to another internal extension, that extension quickly rings & then the call is immediately gone & hung up. We are using Polycom firmware 3.3.3.

In troubleshooting this & analyzing the asterisk logs (& asterisk SIP debug), I am seeing a few interesting items. Any help would be appreciated.

For the sake of simplicity I am going to say that extension 20 is the original internal extension & extension 21 is the extension we are trying to transfer to. Here’s what I’ve learned so far:

  Asterisk SIP debugs are clearly showing that the transfer starts & SIP INVITE is sent to ext 21. Ext 21 then sends a SIP message back to asterisk indicating that it is ringing. Asterisk then sends a SIP CANCEL to ext 21. Call is abruptly terminated for all parties.

  Asterisk logs are displaying WARNING messages during the transfer phase as:

WARNING[25423] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
This error repeats 10-11 times quickly (within 1 second) prior to the SIP CANCEL. (see sample of logs below)

  Other interesting lines from the asterisk full log:

VERBOSE[25592] app_dial.c: – Connected line update to SIP/fpbx-1-b0c4ceff-00002104 prevented.
[Jan 5 20:51:30] VERBOSE[25592] app_dial.c: – SIP/fpbx-1-b0c4ceff-00002104 requested special control 20, passing it to SIP/21-00002105
[Jan 5 20:51:30] VERBOSE[25592] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’ in macro ‘dial-one’
[Jan 5 20:51:30] VERBOSE[25592] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’ in macro ‘exten-vm’

  In looking for the slin codec's use in our system, it is not permitted in our system.

a. We use an upstream SIP trunk provider for PSTN connectivity. That trunk’s codes are configured as disallow=all followed by allow=ulaw&g729

b. Our normal sip.conf settings for all internal phones are: disallow=all allow=g722 allow=ulaw allow=alaw allow=gsm

  So it would seem that slin is not even in use on our system. So why then does it seem like a sip device is asking to use slin? The only thing I can find if I grep /var/log/asterisk/full for slin is:

[Jan 5 19:50:40] VERBOSE[24133] file.c: – <SIP/fpbx-2-b0c4ceff-000020bf> Playing ‘/var/spool/asterisk/voicemail/default/21/unavail.slin’ (language ‘en’)

So it appears that our audio recordings for voicemail are in slin format?

I am not an expert with all of this, but I am doing my best to try to put the pieces together. So again, just to recap, the problem I need to solve is why are blind transfers calls getting terminated when the call being transferred originated as an outbound call from one of our internal Polycom phones.

Any help would be GREATLY appreciated!

Just a greater excerpt from the logs:

[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Goto (macro-dial-one,s,30)
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:30] Set(“SIP/fpbx-1-b0c4ceff-00002104”, “D_OPTIONS=
tr”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:31] ExecIf(“SIP/fpbx-1-b0c4ceff-00002104”, “0?SIPAd
dHeader(Alert-Info: )”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:32] ExecIf(“SIP/fpbx-1-b0c4ceff-00002104”, “0?SIPAd
dHeader()”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:33] ExecIf(“SIP/fpbx-1-b0c4ceff-00002104”, “0?Set(C
HANNEL(musicclass)=)”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:34] GosubIf(“SIP/fpbx-1-b0c4ceff-00002104”, “0?qwai
t,1”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:35] Set(“SIP/fpbx-1-b0c4ceff-00002104”, “__CWIGNORE
=”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:36] Set(“SIP/fpbx-1-b0c4ceff-00002104”, “__KEEPCID=
TRUE”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:37] GotoIf(“SIP/fpbx-1-b0c4ceff-00002104”, “0?usego
to,1”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:38] GotoIf(“SIP/fpbx-1-b0c4ceff-00002104”, “0?godia
l”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:39] Set(“SIP/fpbx-1-b0c4ceff-00002104”, “CONNECTEDL
INE(name,i)=Kyle”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:40] Set(“SIP/fpbx-1-b0c4ceff-00002104”, “CONNECTEDL
INE(num)=21”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:41] Set(“SIP/fpbx-1-b0c4ceff-00002104”, “D_OPTIONS=trI”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-dial-one:42] Dial(“SIP/fpbx-1-b0c4ceff-00002104”, “SIP/21,15,trI”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] netsock2.c: == Using SIP RTP TOS bits 184
[Jan 5 20:51:30] VERBOSE[25592] netsock2.c: == Using SIP RTP CoS mark 5
[Jan 5 20:51:30] VERBOSE[25592] app_dial.c: – Called SIP/21
[Jan 5 20:51:30] VERBOSE[25592] app_dial.c: – Connected line update to SIP/fpbx-1-b0c4ceff-00002104 prevented.
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] VERBOSE[25592] app_dial.c: – SIP/21-00002105 is ringing
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] WARNING[25592] chan_sip.c: Asked to transmit frame type slin, while native formats is 0x4 (ulaw) read/write = 0x4 (ulaw)/0x4 (ulaw)
[Jan 5 20:51:30] VERBOSE[25592] app_dial.c: – SIP/fpbx-1-b0c4ceff-00002104 requested special control 20, passing it to SIP/21-00002105
[Jan 5 20:51:30] VERBOSE[25592] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’ in macro ‘dial-one’
[Jan 5 20:51:30] VERBOSE[25592] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’ in macro ‘exten-vm’
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: == Spawn extension (from-internal-xfer, 21, 2) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [h at from-internal-xfer:1] Macro(“SIP/fpbx-1-b0c4ceff-00002104”, “hangupcall”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-hangupcall:1] GotoIf(“SIP/fpbx-1-b0c4ceff-00002104”, “1?theend”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Goto (macro-hangupcall,s,3)
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: – Executing [s at macro-hangupcall:3] Hangup(“SIP/fpbx-1-b0c4ceff-00002104”, “”) in new stack
[Jan 5 20:51:30] VERBOSE[25592] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’ in macro ‘hangupcall’
[Jan 5 20:51:30] VERBOSE[25592] pbx.c: == Spawn extension (from-internal-xfer, h, 1) exited non-zero on ‘SIP/fpbx-1-b0c4ceff-00002104’

Thanks,

dkmortensen · January 23, 2012, 9:21pm

FYI, I did originally post this to Asterisk-Users mailing list at:
http://lists.digium.com/pipermail/asterisk-users/2012-January/269178.html

So far only one other user is reporting the same issue. Anyone here experiencing the issue? Any ideas? Could this actually be something relating to the FreePBX-generated dial plan?

Thanks.

dkmortensen · January 23, 2012, 10:00pm

I can transfer the person I called to a voicemail vox (transferring to *+) and that works just fine. Additionally I just upgraded the Polycom firmware on 1 phone to 3.3.4. Didn’t make a difference whether I started the initial call from that phone & tried to transfer to another, or whether I started the initial call from another & tried to transfer to it.

I also have a Polycom KIRK 2010 phone. I tried using it in the equation & the same problem exists. Also the other user in the asterisk-users list who reported the problem tested the issue with softphones & it is present there too.

So it would seem that it is probably either an asterisk issue, or a FreePBX issue, but not necessarily an issue caused by the endpoints themselves. Any thoughts? I’m pretty much stuck. I think all I can still try to do is downgrade asterisk and/or FreePBX. Or upgrade FreePBX. If I knew for sure where the issue existed, then it’s possible I could implement a work-around. But presently I really can’t say for sure.

Again, I appreciate any help you can lend.

dunwright · April 28, 2013, 5:36am

Doug, I'm curious, did you ever resolve this issue? I'm having call transfer problems as well with not much love from the "community" or the vendors we're actually paying to manage the platform for us. -Chris