Probably site specific call xfer problem

Axelson · August 24, 2010, 9:43am

This is really bugging me and annoying my client!

I have a problem where one client is unable to successfully transfer (blind or announced) an external call from an extension in their office to another extension again in their office.

On that particular server, I have 7 other clients at different locations, most of which have the same model desk-phones (Linksys SPA921) with identical configurations and all of these clients can transfer okay.

The bit that really confuses me is that they can transfer internal (on switch) calls with no problem.

Any ideas? The only differential is the clients internet connection and router.

Any help VERY gratefully received!

dereklinrs · August 24, 2010, 3:16pm

hi,

what do u see in the asterisk cli when call transfer fails?

regards,

Axelson · August 24, 2010, 8:28pm

Hi,

Thanks for the reply.

The cli simply shows the correct cli.

If it helps, I have included the entire trace in the code block below.

Notice at 14:07:56 the extension I am transferring the call to is answered and then I initiate the attended transfer at 14:08:00 where by the incoming trunk call hangup is initiated.

[Aug 23 14:07:38] VERBOSE[2471] netsock.c:   == Using SIP RTP TOS bits 184
[Aug 23 14:07:38] VERBOSE[2471] netsock.c:   == Using SIP RTP CoS mark 5
[Aug 23 14:07:38] VERBOSE[2471] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug 23 14:07:38] VERBOSE[2471] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-sip-external:1] NoOp

("SIP/*IPremoved*:5061-00001184", "Received incoming SIP connection from unknown peer to 

*numremoved*") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-sip-external:2] Set

("SIP/*IPremoved*:5061-00001184", "DID=*numremoved*") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-sip-external:3] Goto

("SIP/*IPremoved*:5061-00001184", "s,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (from-sip-external,s,1)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@from-sip-external:1] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?checklang:noanonymous") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (from-sip-external,s,2)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@from-sip-external:2] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?setlanguage:from-trunk,*numremoved*,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (from-trunk,*numremoved*,1)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:1] Set

("SIP/*IPremoved*:5061-00001184", "__FROM_DID=*numremoved*") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:2] Gosub

("SIP/*IPremoved*:5061-00001184", "app-blacklist-check,s,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@app-blacklist-check:1] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?blacklisted") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@app-blacklist-check:2] Set

("SIP/*IPremoved*:5061-00001184", "CALLED_BLACKLIST=1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@app-blacklist-check:3] Return

("SIP/*IPremoved*:5061-00001184", "") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:3] ExecIf

("SIP/*IPremoved*:5061-00001184", "0 ?Set(CALLERID(name)=*clidremoved*)") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:4] Set

("SIP/*IPremoved*:5061-00001184", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:5] Set

("SIP/*IPremoved*:5061-00001184", "CALLERPRES()=allowed_not_screened") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:6] Set

("SIP/*IPremoved*:5061-00001184", "_RGPREFIX=YA: ") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:7] Set

("SIP/*IPremoved*:5061-00001184", "CALLERID(name)=YA: *clidremoved*") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [*numremoved*@from-trunk:8] Goto

("SIP/*IPremoved*:5061-00001184", "timeconditions,9,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (timeconditions,9,1)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [9@timeconditions:1] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,sat-sun,*,*?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [9@timeconditions:2] Goto

("SIP/*IPremoved*:5061-00001184", "timeconditions,8,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (timeconditions,8,1)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:1] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,31,may?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:2] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,30,aug?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:3] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,27-28,dec?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:4] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,25-26,dec?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:5] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,2-5,apr?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:6] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,1,jan?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:7] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,3,may?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:8] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "*,*,3,jan?timeconditions,6,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [8@timeconditions:9] Goto

("SIP/*IPremoved*:5061-00001184", "timeconditions,7,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (timeconditions,7,1)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [7@timeconditions:1] GotoIfTime

("SIP/*IPremoved*:5061-00001184", "10:00-16:00,mon-fri,*,*?ext-group,620,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (ext-group,620,1)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:1] Macro("SIP/*IPremoved*:5061

-00001184", "user-callerid,") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:1] Set

("SIP/*IPremoved*:5061-00001184", "AMPUSER=*clidremoved*") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?report") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf

("SIP/*IPremoved*:5061-00001184", "1?Set(REALCALLERIDNUM=*clidremoved*)") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:4] Set

("SIP/*IPremoved*:5061-00001184", "AMPUSER=") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:5] Set

("SIP/*IPremoved*:5061-00001184", "AMPUSERCIDNAME=") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?report") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-user-callerid,s,9)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:9] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?continue") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:10] Set

("SIP/*IPremoved*:5061-00001184", "__TTL=64") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:11] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?continue") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-user-callerid,s,18)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-user-callerid:18] NoOp

("SIP/*IPremoved*:5061-00001184", "Using CallerID "YA: *clidremoved*" <*clidremoved*>") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:2] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?skipdb") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (ext-group,620,4)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:4] Set("SIP/*IPremoved*:5061-

00001184", "__NODEST=") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:5] Set("SIP/*IPremoved*:5061-

00001184", "__BLKVM_OVERRIDE=BLKVM/620/SIP/*IPremoved*:5061-00001184") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:6] Set("SIP/*IPremoved*:5061-

00001184", "__BLKVM_BASE=620") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:7] Set("SIP/*IPremoved*:5061-

00001184", "DB(BLKVM/620/SIP/*IPremoved*:5061-00001184)=TRUE") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:8] Set("SIP/*IPremoved*:5061-

00001184", "RRNODEST=") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:9] Set("SIP/*IPremoved*:5061-

00001184", "__NODEST=620") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:10] GosubIf

("SIP/*IPremoved*:5061-00001184", "0?sub-rgsetcid,s,1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:11] Set("SIP/*IPremoved*:5061-

00001184", "RecordMethod=Group") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:12] Macro

("SIP/*IPremoved*:5061-00001184", "record-enable,221-222-223,Group") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?check") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,4)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:4] ExecIf

("SIP/*IPremoved*:5061-00001184", "0?MacroExit()") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:5] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?Group:OUT") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,6)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:6] Set

("SIP/*IPremoved*:5061-00001184", "LOOPCNT=3") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:7] Set

("SIP/*IPremoved*:5061-00001184", "ITER=1") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:8] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?continue") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,13)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:13] Set

("SIP/*IPremoved*:5061-00001184", "ITER=2") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:14] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?begin") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,8)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:8] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?continue") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,13)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:13] Set

("SIP/*IPremoved*:5061-00001184", "ITER=3") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:14] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?begin") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,8)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:8] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?continue") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-record-enable,s,13)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:13] Set

("SIP/*IPremoved*:5061-00001184", "ITER=4") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:14] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?begin") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:15] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?IN") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-record-enable:16] ExecIf

("SIP/*IPremoved*:5061-00001184", "1?MacroExit()") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:13] Set("SIP/*IPremoved*:5061-

00001184", "RingGroupMethod=ringall") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [620@ext-group:14] Macro

("SIP/*IPremoved*:5061-00001184", "dial,15,trwW,221-222-223") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/*IPremoved*:5061

-00001184", "1?dial") in new stack
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Goto (macro-dial,s,3)
[Aug 23 14:07:38] VERBOSE[3757] pbx.c:     -- Executing [s@macro-dial:3] AGI("SIP/*IPremoved*:5061-

00001184", "dialparties.agi") in new stack
[Aug 23 14:07:38] VERBOSE[3757] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-

bin/dialparties.agi
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:  dialparties.agi: Starting New Dialparties.agi
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:  dialparties.agi: Caller ID name is 'YA: *clidremoved*' 

number is '*clidremoved*'
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:  dialparties.agi: Methodology of ring is  'ringall'
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Added extension 221 to extension 

map
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Added extension 222 to extension 

map
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Added extension 223 to extension 

map
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Extension 221 cf is disabled
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Extension 222 cf is disabled
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Extension 223 cf is disabled
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Extension 221 do not disturb is 

disabled
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Extension 222 do not disturb is 

disabled
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Extension 223 do not disturb is 

disabled
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: dbset CALLTRACE/221 to 

*clidremoved*
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: dbset CALLTRACE/222 to 

*clidremoved*
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: dbset CALLTRACE/223 to 

*clidremoved*
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- dialparties.agi: Filtered ARG3: 221-222-223
[Aug 23 14:07:39] VERBOSE[3757] res_agi.c:     -- <SIP/*IPremoved*:5061-00001184>AGI Script 

dialparties.agi completed, returning 0
[Aug 23 14:07:39] VERBOSE[3757] pbx.c:     -- Executing [s@macro-dial:7] Dial("SIP/*IPremoved*:5061-

00001184", "SIP/221&SIP/222&SIP/223,15,trwWM(auto-blkvm)") in new stack
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP RTP TOS bits 184
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP RTP CoS mark 5
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug 23 14:07:39] VERBOSE[3757] app_dial.c:     -- Called 221
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP RTP TOS bits 184
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP RTP CoS mark 5
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug 23 14:07:39] VERBOSE[3757] app_dial.c:     -- Called 222
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP RTP TOS bits 184
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP RTP CoS mark 5
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug 23 14:07:39] VERBOSE[3757] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug 23 14:07:39] VERBOSE[3757] app_dial.c:     -- Called 223
[Aug 23 14:07:39] VERBOSE[3757] app_dial.c:     -- SIP/221-00001185 is ringing
[Aug 23 14:07:39] VERBOSE[3757] app_dial.c:     -- SIP/223-00001187 is ringing
[Aug 23 14:07:39] VERBOSE[3757] app_dial.c:     -- SIP/222-00001186 is ringing
[Aug 23 14:07:40] VERBOSE[3757] app_dial.c:     -- SIP/223-00001187 answered SIP/*IPremoved*:5061-

00001184
[Aug 23 14:07:40] VERBOSE[3757] pbx.c:     -- Executing [s@macro-auto-blkvm:1] Set("SIP/223-00001187", 

"__MACRO_RESULT=") in new stack
[Aug 23 14:07:40] VERBOSE[3757] pbx.c:     -- Executing [s@macro-auto-blkvm:2] NoOp("SIP/223-

00001187", "Deleting: BLKVM/620/SIP/*IPremoved*:5061-00001184 TRUE") in new stack
[Aug 23 14:07:50] VERBOSE[3757] res_musiconhold.c:     -- Started music on hold, class 'default', on 

SIP/*IPremoved*:5061-00001184
[Aug 23 14:07:53] VERBOSE[2471] netsock.c:   == Using SIP RTP TOS bits 184
[Aug 23 14:07:53] VERBOSE[2471] netsock.c:   == Using SIP RTP CoS mark 5
[Aug 23 14:07:53] VERBOSE[2471] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug 23 14:07:53] VERBOSE[2471] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [222@custom-trunk-ya-1:1] Set("SIP/223-

00001188", "restprefix=000001") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [222@custom-trunk-ya-1:2] Set("SIP/223-

00001188", "sysextlen=3") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [222@custom-trunk-ya-1:3] Goto("SIP/223-

00001188", "custom-trunk-multi,222,1") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (custom-trunk-multi,222,1)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [222@custom-trunk-multi:1] Goto("SIP/223-

00001188", "from-internal,222,1") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (from-internal,222,1)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [222@from-internal:1] Macro("SIP/223-

00001188", "exten-vm,novm,222") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/223-00001188", 

"user-callerid,") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/223-

00001188", "AMPUSER=223") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/223-

00001188", "0?report") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/223-

00001188", "1?Set(REALCALLERIDNUM=223)") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/223-

00001188", "AMPUSER=223") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/223-

00001188", "AMPUSERCIDNAME=Admin") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/223-

00001188", "0?report") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/223-

00001188", "AMPUSERCID=223") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/223-

00001188", "CALLERID(all)="Admin" <223>") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:9] GotoIf("SIP/223-

00001188", "0?continue") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:10] Set("SIP/223-

00001188", "__TTL=64") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:11] GotoIf("SIP/223-

00001188", "1?continue") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (macro-user-callerid,s,18)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-user-callerid:18] NoOp("SIP/223-

00001188", "Using CallerID "Admin" <223>") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/223-00001188", 

"RingGroupMethod=none") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/223-00001188", 

"VMBOX=novm") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/223-00001188", 

"EXTTOCALL=222") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/223-00001188", 

"CFUEXT=") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:6] Set("SIP/223-00001188", 

"CFBEXT=") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:7] Set("SIP/223-00001188", 

"RT=""") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:8] Macro("SIP/223-00001188", 

"record-enable,222,IN") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/223-

00001188", "1?check") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (macro-record-enable,s,4)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-record-enable:4] ExecIf("SIP/223-

00001188", "0?MacroExit()") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-record-enable:5] GotoIf("SIP/223-

00001188", "0?Group:OUT") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (macro-record-enable,s,15)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-record-enable:15] GotoIf("SIP/223-

00001188", "1?IN") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (macro-record-enable,s,20)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-record-enable:20] ExecIf("SIP/223-

00001188", "1?MacroExit()") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-exten-vm:9] Macro("SIP/223-00001188", 

"dial,"",trwW,222") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/223-00001188", 

"1?dial") in new stack
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Goto (macro-dial,s,3)
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-dial:3] AGI("SIP/223-00001188", 

"dialparties.agi") in new stack
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-

bin/dialparties.agi
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:  dialparties.agi: Starting New Dialparties.agi
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:  dialparties.agi: Caller ID name is 'Admin' number is '223'
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:  dialparties.agi: Methodology of ring is  'none'
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- dialparties.agi: Added extension 222 to extension 

map
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- dialparties.agi: Extension 222 cf is disabled
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- dialparties.agi: Extension 222 do not disturb is 

disabled
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:  dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- dialparties.agi: dbset CALLTRACE/222 to 223
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- dialparties.agi: Filtered ARG3: 222
[Aug 23 14:07:53] VERBOSE[3760] res_agi.c:     -- <SIP/223-00001188>AGI Script dialparties.agi 

completed, returning 0
[Aug 23 14:07:53] VERBOSE[3760] pbx.c:     -- Executing [s@macro-dial:7] Dial("SIP/223-00001188", 

"SIP/222,"",trwW") in new stack
[Aug 23 14:07:53] VERBOSE[3760] netsock.c:   == Using SIP RTP TOS bits 184
[Aug 23 14:07:53] VERBOSE[3760] netsock.c:   == Using SIP RTP CoS mark 5
[Aug 23 14:07:53] VERBOSE[3760] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug 23 14:07:53] VERBOSE[3760] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug 23 14:07:53] VERBOSE[3760] app_dial.c:     -- Called 222
[Aug 23 14:07:53] VERBOSE[3760] app_dial.c:     -- SIP/222-00001189 is ringing
[Aug 23 14:07:56] VERBOSE[3760] app_dial.c:     -- SIP/222-00001189 answered SIP/223-00001188
[Aug 23 14:08:00] VERBOSE[3757] res_musiconhold.c:     -- Stopped music on hold on 

SIP/*IPremoved*:5061-00001184
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/*IPremoved*:5061-

00001184", "hangupcall") in new stack
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?skiprg") in new stack
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf

("SIP/*IPremoved*:5061-00001184", "0?skipblkvm") in new stack
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [s@macro-hangupcall:5] NoOp

("SIP/*IPremoved*:5061-00001184", "Cleaning Up Block VM Flag: BLKVM/620/SIP/*IPremoved*:5061-

00001184") in new stack
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [s@macro-hangupcall:6] NoOp

("SIP/*IPremoved*:5061-00001184", "Deleting: BLKVM/620/SIP/*IPremoved*:5061-00001184 ") in new stack
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf

("SIP/*IPremoved*:5061-00001184", "1?theend") in new stack
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup

("SIP/*IPremoved*:5061-00001184", "") in new stack
[Aug 23 14:08:04] VERBOSE[3757] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non

-zero on 'SIP/*IPremoved*:5061-00001184' in macro 'hangupcall'
[Aug 23 14:08:04] VERBOSE[3757] features.c:   == Spawn extension (macro-dial, h, 1) exited non-zero on 

'SIP/*IPremoved*:5061-00001184'
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/223-00001188", 

"hangupcall") in new stack
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/223-

00001188", "1?skiprg") in new stack
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/223-

00001188", "1?skipblkvm") in new stack
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/223-

00001188", "1?theend") in new stack
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/223-

00001188", "") in new stack
[Aug 23 14:08:04] VERBOSE[3760] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non

-zero on 'SIP/223-00001188' in macro 'hangupcall'
[Aug 23 14:08:04] VERBOSE[3757] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero 

on 'SIP/*IPremoved*:5061-00001184' in macro 'dial'
[Aug 23 14:08:04] VERBOSE[3757] pbx.c:   == Spawn extension (ext-group, 620, 14) exited non-zero on 

'SIP/*IPremoved*:5061-00001184'
[Aug 23 14:08:04] VERBOSE[3760] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero 

on 'SIP/223-00001188' in macro 'dial'
[Aug 23 14:08:04] VERBOSE[3760] app_macro.c:   == Spawn extension (macro-exten-vm, s, 9) exited non-

zero on 'SIP/223-00001188' in macro 'exten-vm'
[Aug 23 14:08:04] VERBOSE[3760] pbx.c:   == Spawn extension (from-internal, 222, 1) exited non-zero on 

'SIP/223-00001188'

The next code block contains the last transaction of the forward for a working transfer. Same server, same handsets, same config, just different extension numbers (!) and location - i.e. behind a different router.

Called extension answers...

[Aug 24 10:24:44] VERBOSE[7971] app_dial.c:     -- SIP/3121-00001227 is ringing
[Aug 24 10:24:48] VERBOSE[7971] app_dial.c:     -- SIP/3121-00001227 answered SIP/201-00001226
[Aug 24 10:24:52] VERBOSE[2471] res_musiconhold.c:     -- Stopped music on hold on SIP/*IPremoved*-00001222
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/201-00001226<ZOMBIE>", "hangupcall") in new stack
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/201-00001226<ZOMBIE>", "1?skiprg") in new stack
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/201-00001226<ZOMBIE>", "1?skipblkvm") in new stack
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/201-00001226<ZOMBIE>", "1?theend") in new stack
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/201-00001226<ZOMBIE>", "") in new stack
[Aug 24 10:24:52] VERBOSE[7969] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/201-00001226<ZOMBIE>' in macro 'hangupcall'
[Aug 24 10:24:52] VERBOSE[7969] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/201-00001226<ZOMBIE>' in macro 'dial'
[Aug 24 10:24:52] VERBOSE[7969] pbx.c:   == Spawn extension (ext-group, 600, 14) exited non-zero on 'SIP/201-00001226<ZOMBIE>'
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/*IPremoved*-00001222", "hangupcall") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/*IPremoved*-00001222", "1?skiprg") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/*IPremoved*-00001222", "0?skipblkvm") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:5] NoOp("SIP/*IPremoved*-00001222", "Cleaning Up Block VM Flag: BLKVM/600/SIP/*IPremoved*-00001222") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:6] NoOp("SIP/*IPremoved*-00001222", "Deleting: BLKVM/600/SIP/*IPremoved*-00001222 ") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/*IPremoved*-00001222", "1?theend") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/*IPremoved*-00001222", "") in new stack
[Aug 24 10:24:58] VERBOSE[7971] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/*IPremoved*-00001222' in macro 'hangupcall'
[Aug 24 10:24:58] VERBOSE[7971] features.c:   == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/*IPremoved*-00001222'
[Aug 24 10:24:58] VERBOSE[7971] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/*IPremoved*-00001222' in macro 'dial'
[Aug 24 10:24:58] VERBOSE[7971] app_macro.c:   == Spawn extension (macro-exten-vm, s, 9) exited non-zero on 'SIP/*IPremoved*-00001222' in macro 'exten-vm'
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:   == Spawn extension (from-internal, 3121, 1) exited non-zero on 'SIP/*IPremoved*-00001222'
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [h@from-internal:1] Macro("SIP/*IPremoved*-00001222", "hangupcall") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/*IPremoved*-00001222", "1?skiprg") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/*IPremoved*-00001222", "0?skipblkvm") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:5] NoOp("SIP/*IPremoved*-00001222", "Cleaning Up Block VM Flag: BLKVM/600/SIP/*IPremoved*-00001222") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:6] NoOp("SIP/*IPremoved*-00001222", "Deleting: BLKVM/600/SIP/*IPremoved*-00001222 ") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/*IPremoved*-00001222", "1?theend") in new stack
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/*IPremoved*-00001222", "") in new stack
[Aug 24 10:24:58] VERBOSE[7971] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/*IPremoved*-00001222' in macro 'hangupcall'
[Aug 24 10:24:58] VERBOSE[7971] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/*IPremoved*-00001222'
[Aug 24 10:24:59] VERBOSE[2471] chan_sip.c:     -- Registered SIP '3221' at 94.194.58.133 port 52641
[Aug 24 10:25:53] VERBOSE[2471] chan_sip.c:     -- Registered SIP '3221' at 94.194.58.133 port 52654
[Aug 24 10:26:48] VERBOSE[2471] chan_sip.c:     -- Registered SIP '3221' at 94.194.58.133 port 52705

Any ideas?

Regards
Aaron.

voipcitadel.com · September 6, 2010, 3:03am

is this over a SIP trunking inbound?

-Jake
www.voipcitadel.com

Axelson · September 6, 2010, 7:32am

Yes, the inbound call is arriving over a SIP trunk.
All of my clients are using SIP trunks, most are using the same provider as do I.

voipcitadel.com · September 7, 2010, 12:25am

I think that you could have one of a few issues going on here.

I have seen this with a bad extension, like the GUI didn’t save it properly in the SQL database on the box (if you are using a GUI). A re-save of the extension could fix it.

I also think you may have some router issue or something? Why did that extension re-register 3 times right after the call terminated? That makes me think SIP router issue but I am not sure.

PM me a screen shot of the end of the call please (a little less verbose). You can fine my contact on my site.

-Jake

www.voipcitadel.com

Topic		Replies	Views
Attended external transfers Asterisk Support	4	896	January 16, 2017
Asterisk 13.0.15 and transfer call Asterisk Support	7	329	November 16, 2015
Losing RTP on Call forward From external to another External # Asterisk Support	3	102	March 24, 2024
Calling Party Xfer and Retain Control Asterisk Support	0	188	January 9, 2012
SIP Transfer (REFER) to external SIP address? Asterisk Support	4	1764	April 19, 2013

Probably site specific call xfer problem

Related topics