Transfer Delay with Aastra phones

Forums

I have a thirdlane system with PBX Manager 6.0.1.72 using aastra phones. Model number is irrelevant as it happens on all of them. It could also happen on polycomm phones but I don't have any on my system. (I will soon though) Here is what's happening:
A call comes in and asks to be transferred the caller is transferred properly but the call does not ring on the destination phone and is thought to be lost. About 1 to 1.5 minutes later the call finally rings to the destination phone. The caller hears a brief moment of hold music then nothing for the entire time until it begins to ring on the destination phone.
I cannot recreate it and it's definitely not operator error as I have been both the recipient and the sender of this occurrence. Here is the log file of one of the incidents.

Any Suggestions or Answers?

[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:58] Set("SIP/244-TravisPointe-b68d2db0", "CONFIRM=") in new stack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: Set
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:59] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?getblock") in newstack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,64)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] DEBUG[32365] func_db.c: DB: TL/TravisPointe-223/BLOCK not found in database.
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:64] Set("SIP/244-TravisPointe-b68d2db0", "BLOCK=") in new stack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: Set
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:65] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?getrecord") in newstack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,69)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:69] Set("SIP/244-TravisPointe-b68d2db0", "RECORD=") in new stack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: Set

[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:70] NoOp("SIP/244-TravisPointe-b68d2db0", "calleridnum=244 ") innew stack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: NoOp
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:71] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?screening") in newstack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,103)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:103] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?recording") in new stack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,129)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:129] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?forwarding") in new stack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,131)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf

[Feb 24 17:21:13] DEBUG[32365] func_db.c: DB: TL/TravisPointe-223/CFAnot found in database.
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:131] Set("SIP/244-TravisPointe-b68d2db0", "FORWARD=") in newstack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: Set
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:132] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?followmecheck")in new stack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,139)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] DEBUG[32365] func_db.c: DB: TL/TravisPointe-223/CFNAnot found in database.
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:139] Set("SIP/244-TravisPointe-b68d2db0", "FORWARD=") in newstack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: Set
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:140] Set("SIP/244-TravisPointe-b68d2db0", "__FOLLOWME=0") in new stack

[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: Set
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:141] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?checkchannel") in new stack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,153)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:153] ChanIsAvail("SIP/244-TravisPointe-b68d2db0","SIP/223-TravisPointe") in new stack
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application:ChanIsAvail
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:154] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?chanavail") in newstack
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,156)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:156] GotoIf("SIP/244-TravisPointe-b68d2db0", "1?dial") in newstack

[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Goto(macro-tl-userexten-base,s,162)
[Feb 24 17:21:13] DEBUG[32365] app_macro.c: Executed application: GotoIf
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Executing[s@macro-tl-userexten-base:162] Dial("SIP/244-TravisPointe-b68d2db0", "SIP/223-TravisPointe|20|rtT") in new stack
[Feb 24 17:21:13] VERBOSE[7547] logger.c: Extension Changed223[local-extensions-TravisPointe] new state Ringing for Notify User 244-TravisPointe
[Feb 24 17:21:13] VERBOSE[7547] logger.c: Extension Changed223[local-extensions-TravisPointe] new state Ringing for Notify User 228-TravisPointe
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- Called223-TravisPointe
[Feb 24 17:21:13] VERBOSE[32365] logger.c: -- SIP/223-TravisPointe-089687b0 is ringing

Submitted by eeman on Sat, 02/27/2010 Permalink

thats really wierd... use softphone for testing too so that you can rule out just the phone itself.

Submitted by IVSCOMM on Wed, 03/10/2010 Permalink

Has any one else had anything like this happening??????????

Submitted by eeman on Wed, 03/10/2010 Permalink

i never heard if you tested with a softphone to see if the problem exists outside aastra phones.

Submitted by IVSCOMM on Thu, 03/11/2010 Permalink

Tested today between a Softphone (eyebeam/xlite) and a Polycomm IP650 to remove any reference to aastra. I called in with my cell phone, answered on the polycomm and then proceeded to transfer the call back and forth after about the 25th time i was getting a little frustrated and then it finally happened. The exact same symptom as mentioned above. I will attempt to get the log and download them later. My log is a pretty massive file.

Submitted by eeman on Thu, 03/11/2010 Permalink

what version of asterisk are you running? i remember a vague transfer problem with one of the releases?