Inbound Caller gets Fast Busy and Extension gets ringing

MarkKGreenway asked:

Inbound caller (1636) calls a sipstation direct dial to my phone on my desk.

Cellphone sounds like fast busy but then desk phone rings.

Cant connect the call. then when desk phone hangs up It rings again (to no avail as well)
sometimes 3 or more phantom calls.

Asterisk Log :

    [2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/fpbx-1-f23bc5a3-0000011f", "THISDIAL=SIP/311") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-1-f23bc5a3-0000011f", "") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("SIP/fpbx-1-f23bc5a3-0000011f", "DSTRING=SIP/311&") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("SIP/fpbx-1-f23bc5a3-0000011f", "ITER=2") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?begin") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("SIP/fpbx-1-f23bc5a3-0000011f", "DSTRING=SIP/311") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("SIP/fpbx-1-f23bc5a3-0000011f", "") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?nodial") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?skiptrace") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:29] GosubIf("SIP/fpbx-1-f23bc5a3-0000011f", "1?ctset,1():ctclear,1()") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("SIP/fpbx-1-f23bc5a3-0000011f", "DB(CALLTRACE/311)=+17274531636") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("SIP/fpbx-1-f23bc5a3-0000011f", "") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:30] Set("SIP/fpbx-1-f23bc5a3-0000011f", "D_OPTIONS=tr") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?SIPAddHeader(Alert-Info: )") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?SIPAddHeader()") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?Set(CHANNEL(musicclass)=)") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?qwait,1()") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:35] Set("SIP/fpbx-1-f23bc5a3-0000011f", "__CWIGNORE=") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:36] Set("SIP/fpbx-1-f23bc5a3-0000011f", "__KEEPCID=TRUE") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?usegoto,1") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:38] GotoIf("SIP/fpbx-1-f23bc5a3-0000011f", "1?godial") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Goto (macro-dial-one,s,42)
[2012-08-01 09:08:01] VERBOSE[7036] pbx.c: -- Executing [s@macro-dial-one:42] Dial("SIP/fpbx-1-f23bc5a3-0000011f", "SIP/311,15,tr") in new stack
[2012-08-01 09:08:01] VERBOSE[7036] netsock2.c: == Using SIP RTP TOS bits 184
[2012-08-01 09:08:01] VERBOSE[7036] netsock2.c: == Using SIP RTP CoS mark 5
[2012-08-01 09:08:01] VERBOSE[7036] app_dial.c: -- Called SIP/311
[2012-08-01 09:08:06] VERBOSE[7035] pbx.c: -- Executing [h@from-did-direct:1] Macro("SIP/fpbx-2-f23bc5a3-0000011d", "hangupcall,") in new stack
[2012-08-01 09:08:11] WARNING[3921] chan_sip.c: Retransmission timeout reached on transmission 3e57de11239b49f10930969c7e23d1ca@50.58.42.81:5060 for seqno 102 (Critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 9983ms with no response
[2012-08-01 09:08:11] WARNING[3921] chan_sip.c: Hanging up call 3e57de11239b49f10930969c7e23d1ca@50.58.42.81:5060 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[2012-08-01 09:08:11] VERBOSE[7036] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1)
[2012-08-01 09:08:11] VERBOSE[7035] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/fpbx-2-f23bc5a3-0000011d", "1?theend") in new stack
[2012-08-01 09:08:11] VERBOSE[7035] pbx.c: -- Goto (macro-hangupcall,s,3)
[2012-08-01 09:08:11] VERBOSE[7035] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/fpbx-2-f23bc5a3-0000011d", "0?Set(CDR(recordingfile)=)") in new stack
[2012-08-01 09:08:11] VERBOSE[7035] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/fpbx-2-f23bc5a3-0000011d", "") in new stack
[2012-08-01 09:08:11] VERBOSE[7035] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-2-f23bc5a3-0000011d' in macro 'hangupcall'
[2012-08-01 09:08:11] VERBOSE[7035] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-2-f23bc5a3-0000011d'
[2012-08-01 09:08:16] VERBOSE[7036] pbx.c: -- Executing [h@from-did-direct:1] Macro("SIP/fpbx-1-f23bc5a3-0000011f", "hangupcall,") in new stack
[2012-08-01 09:08:16] VERBOSE[7036] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/fpbx-1-f23bc5a3-0000011f", "1?theend") in new stack
[2012-08-01 09:08:16] VERBOSE[7036] pbx.c: -- Goto (macro-hangupcall,s,3)
[2012-08-01 09:08:16] VERBOSE[7036] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/fpbx-1-f23bc5a3-0000011f", "0?Set(CDR(recordingfile)=)") in new stack
[2012-08-01 09:08:16] VERBOSE[7036] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/fpbx-1-f23bc5a3-0000011f", "") in new stack
[2012-08-01 09:08:16] VERBOSE[7036] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-f23bc5a3-0000011f' in macro 'hangupcall'
[2012-08-01 09:08:16] VERBOSE[7036] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-f23bc5a3-0000011f'
[2012-08-01 09:08:18] WARNING[3921] chan_sip.c: Retransmission timeout reached on transmission 9679a4d7-569e-1230-28bb-40404edf54cf for seqno 31584440 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6400ms with no response
[2012-08-01 09:08:23] WARNING[3921] chan_sip.c: Retransmission timeout reached on transmission 9836b680-569e-1230-28bb-40404edf54cf for seqno 31584441 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6400ms with no response
[2012-08-01 09:09:21] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-08-01 09:09:26] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-08-01 09:11:16] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-08-01 09:11:21] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-08-01 09:11:45] VERBOSE[7033] asterisk.c: -- Remote UNIX connection disconnected
[2012-08-01 09:13:11] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-08-01 09:13:16] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-08-01 09:15:06] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-08-01 09:15:11] VERBOSE[3921] dnsmgr.c: > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-08-01 09:15:21] VERBOSE[3921] netsock2.c: == Using SIP RTP TOS bits 184
[2012-08-01 09:15:21] VERBOSE[3921] netsock2.c: == Using SIP RTP CoS mark 5
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [7272225497@from-pstn:1] Set("SIP/fpbx-2-f23bc5a3-00000121", "__FROM_DID=7272225497") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [7272225497@from-pstn:2] Set("SIP/fpbx-2-f23bc5a3-00000121", "CDR(did)=7272225497") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [7272225497@from-pstn:3] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0 ?Set(CALLERID(name)=+17274531636)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [7272225497@from-pstn:4] Set("SIP/fpbx-2-f23bc5a3-00000121", "__CALLINGPRES_SV=prohib_not_screened") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [7272225497@from-pstn:5] Set("SIP/fpbx-2-f23bc5a3-00000121", "CALLERPRES()=allowed_not_screened") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [7272225497@from-pstn:6] Goto("SIP/fpbx-2-f23bc5a3-00000121", "from-did-direct,311,1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (from-did-direct,311,1)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [311@from-did-direct:1] Set("SIP/fpbx-2-f23bc5a3-00000121", "__RINGTIMER=15") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [311@from-did-direct:2] Macro("SIP/fpbx-2-f23bc5a3-00000121", "exten-vm,311,311,0,0,0") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("SIP/fpbx-2-f23bc5a3-00000121", "user-callerid,") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/fpbx-2-f23bc5a3-00000121", "AMPUSER=+17274531636") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?report") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "1?Set(REALCALLERIDNUM=+17274531636)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/fpbx-2-f23bc5a3-00000121", "AMPUSER=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/fpbx-2-f23bc5a3-00000121", "AMPUSERCIDNAME=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?report") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-user-callerid,s,11)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:11] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?continue") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:12] Set("SIP/fpbx-2-f23bc5a3-00000121", "__TTL=64") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?continue") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-user-callerid,s,24)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:24] Set("SIP/fpbx-2-f23bc5a3-00000121", "CALLERID(number)=+17274531636") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:25] Set("SIP/fpbx-2-f23bc5a3-00000121", "CALLERID(name)=+17274531636") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/fpbx-2-f23bc5a3-00000121", "CHANNEL(language)=en") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:2] Set("SIP/fpbx-2-f23bc5a3-00000121", "RingGroupMethod=none") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:3] Set("SIP/fpbx-2-f23bc5a3-00000121", "__EXTTOCALL=311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:4] Set("SIP/fpbx-2-f23bc5a3-00000121", "__PICKUPMARK=311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:5] Set("SIP/fpbx-2-f23bc5a3-00000121", "RT=15") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:6] Gosub("SIP/fpbx-2-f23bc5a3-00000121", "sub-record-check,s,1(exten,311,)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?check") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (sub-record-check,s,6)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/fpbx-2-f23bc5a3-00000121", "__MON_FMT=wav") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?next") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (sub-record-check,s,10)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Return()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?exten,1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/fpbx-2-f23bc5a3-00000121", "__REC_STATUS=INITIALIZED") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Set(__REC_POLICY_MODE=)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/fpbx-2-f23bc5a3-00000121", "NOW=1343826921") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/fpbx-2-f23bc5a3-00000121", "__DAY=01") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/fpbx-2-f23bc5a3-00000121", "__MONTH=08") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/fpbx-2-f23bc5a3-00000121", "__YEAR=2012") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/fpbx-2-f23bc5a3-00000121", "__TIMESTR=20120801-091521") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/fpbx-2-f23bc5a3-00000121", "__FROMEXTEN=+17274531636") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/fpbx-2-f23bc5a3-00000121", "__CALLFILENAME=exten-311-+17274531636-20120801-091521-1343826921.481") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@sub-record-check:21] Goto("SIP/fpbx-2-f23bc5a3-00000121", "exten,1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (sub-record-check,exten,1)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [exten@sub-record-check:1] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?callee") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [exten@sub-record-check:2] Set("SIP/fpbx-2-f23bc5a3-00000121", "__REC_POLICY_MODE=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [exten@sub-record-check:3] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?caller") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [exten@sub-record-check:4] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?callee") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (sub-record-check,exten,8)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [exten@sub-record-check:8] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "0?record,1(exten,311,+17274531636)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [exten@sub-record-check:9] Return("SIP/fpbx-2-f23bc5a3-00000121", "") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-exten-vm:7] Macro("SIP/fpbx-2-f23bc5a3-00000121", "dial-one,15,tr,311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:1] Set("SIP/fpbx-2-f23bc5a3-00000121", "DEXTEN=311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:2] Set("SIP/fpbx-2-f23bc5a3-00000121", "DIALSTATUS_CW=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "0?screen,1()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "0?cf,1()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?skip1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-dial-one,s,8)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?nodial") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?continue") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:10] Set("SIP/fpbx-2-f23bc5a3-00000121", "EXTHASCW=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?next1:cwinusebusy") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-dial-one,s,12)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:12] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?docfu:skip3") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-dial-one,s,16)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:16] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?next2:continue") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-dial-one,s,17)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:17] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?continue") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-dial-one,s,25)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?nodial") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "1?dstring,1():dlocal,1()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("SIP/fpbx-2-f23bc5a3-00000121", "DSTRING=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("SIP/fpbx-2-f23bc5a3-00000121", "DEVICES=311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Return()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Set(DEVICES=11)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("SIP/fpbx-2-f23bc5a3-00000121", "LOOPCNT=1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("SIP/fpbx-2-f23bc5a3-00000121", "ITER=1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("SIP/fpbx-2-f23bc5a3-00000121", "THISDIAL=SIP/311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "1?zap2dahdi,1()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Return()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-2-f23bc5a3-00000121", "NEWDIAL=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/fpbx-2-f23bc5a3-00000121", "LOOPCNT2=1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/fpbx-2-f23bc5a3-00000121", "ITER2=1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/fpbx-2-f23bc5a3-00000121", "THISPART2=SIP/311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Set(THISPART2=DAHDI/311)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/fpbx-2-f23bc5a3-00000121", "NEWDIAL=SIP/311&") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/fpbx-2-f23bc5a3-00000121", "ITER2=2") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?begin2") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/fpbx-2-f23bc5a3-00000121", "THISDIAL=SIP/311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-2-f23bc5a3-00000121", "") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("SIP/fpbx-2-f23bc5a3-00000121", "DSTRING=SIP/311&") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("SIP/fpbx-2-f23bc5a3-00000121", "ITER=2") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?begin") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("SIP/fpbx-2-f23bc5a3-00000121", "DSTRING=SIP/311") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("SIP/fpbx-2-f23bc5a3-00000121", "") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?nodial") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?skiptrace") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:29] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "1?ctset,1():ctclear,1()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("SIP/fpbx-2-f23bc5a3-00000121", "DB(CALLTRACE/311)=+17274531636") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("SIP/fpbx-2-f23bc5a3-00000121", "") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:30] Set("SIP/fpbx-2-f23bc5a3-00000121", "D_OPTIONS=tr") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?SIPAddHeader(Alert-Info: )") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?SIPAddHeader()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("SIP/fpbx-2-f23bc5a3-00000121", "0?Set(CHANNEL(musicclass)=)") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("SIP/fpbx-2-f23bc5a3-00000121", "0?qwait,1()") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:35] Set("SIP/fpbx-2-f23bc5a3-00000121", "__CWIGNORE=") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:36] Set("SIP/fpbx-2-f23bc5a3-00000121", "__KEEPCID=TRUE") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "0?usegoto,1") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:38] GotoIf("SIP/fpbx-2-f23bc5a3-00000121", "1?godial") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Goto (macro-dial-one,s,42)
[2012-08-01 09:15:21] VERBOSE[7110] pbx.c: -- Executing [s@macro-dial-one:42] Dial("SIP/fpbx-2-f23bc5a3-00000121", "SIP/311,15,tr") in new stack
[2012-08-01 09:15:21] VERBOSE[7110] netsock2.c: == Using SIP RTP TOS bits 184
[2012-08-01 09:15:21] VERBOSE[7110] netsock2.c: == Using SIP RTP CoS mark 5
[2012-08-01 09:15:21] VERBOSE[7110] app_dial.c: -- Called SIP/311
[2012-08-01 09:15:26] VERBOSE[3921] netsock2.c: == Using SIP RTP TOS bits 184
[2012-08-01 09:15:26] VERBOSE[3921] netsock2.c: == Using SIP RTP CoS mark 5
[2012-08-01 09:15:26] NOTICE[3921] chan_sip.c: Peer '604' is now UNREACHABLE! Last qualify: 183
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [7272225497@from-pstn:1] Set("SIP/fpbx-1-f23bc5a3-00000123", "__FROM_DID=7272225497") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [7272225497@from-pstn:2] Set("SIP/fpbx-1-f23bc5a3-00000123", "CDR(did)=7272225497") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [7272225497@from-pstn:3] ExecIf("SIP/fpbx-1-f23bc5a3-00000123", "0 ?Set(CALLERID(name)=+17274531636)") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [7272225497@from-pstn:4] Set("SIP/fpbx-1-f23bc5a3-00000123", "__CALLINGPRES_SV=prohib_not_screened") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [7272225497@from-pstn:5] Set("SIP/fpbx-1-f23bc5a3-00000123", "CALLERPRES()=allowed_not_screened") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [7272225497@from-pstn:6] Goto("SIP/fpbx-1-f23bc5a3-00000123", "from-did-direct,311,1") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Goto (from-did-direct,311,1)
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [311@from-did-direct:1] Set("SIP/fpbx-1-f23bc5a3-00000123", "__RINGTIMER=15") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [311@from-did-direct:2] Macro("SIP/fpbx-1-f23bc5a3-00000123", "exten-vm,311,311,0,0,0") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("SIP/fpbx-1-f23bc5a3-00000123", "user-callerid,") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/fpbx-1-f23bc5a3-00000123", "AMPUSER=+17274531636") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/fpbx-1-f23bc5a3-00000123", "0?report") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/fpbx-1-f23bc5a3-00000123", "1?Set(REALCALLERIDNUM=+17274531636)") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/fpbx-1-f23bc5a3-00000123", "AMPUSER=") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/fpbx-1-f23bc5a3-00000123", "AMPUSERCIDNAME=") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/fpbx-1-f23bc5a3-00000123", "1?report") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Goto (macro-user-callerid,s,11)
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:11] GotoIf("SIP/fpbx-1-f23bc5a3-00000123", "0?continue") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:12] Set("SIP/fpbx-1-f23bc5a3-00000123", "__TTL=64") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/fpbx-1-f23bc5a3-00000123", "1?continue") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Goto (macro-user-callerid,s,24)
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:24] Set("SIP/fpbx-1-f23bc5a3-00000123", "CALLERID(number)=+17274531636") in new stack
[2012-08-01 09:15:26] VERBOSE[7111] pbx.c: -- Executing [s@macro-user-callerid:25] Set("SIP/fpbx-1-f23bc5a3-00000123", "CALLERID(name)=+17274531636") in new stack

My answer:


The important parts of your log are these two WARNING messages:

[2012-08-01 09:08:11] WARNING[3921] chan_sip.c: Retransmission timeout reached on transmission 3e57de11239b49f10930969c7e23d1ca@50.58.42.81:5060 for seqno 102 (Critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 9983ms with no response
[2012-08-01 09:08:11] WARNING[3921] chan_sip.c: Hanging up call 3e57de11239b49f10930969c7e23d1ca@50.58.42.81:5060 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).

This indicates that Asterisk sent a SIP message to your IP phone, but never got a reply back. It was therefore forced to drop the call.

The wiki article linked in the log entry has further information that you can use for debugging this issue. The most likely cause of the problem is a firewall or NAT issue.


View the full question and answer on Server Fault.

Creative Commons License
This work is licensed under a Creative Commons Attribution-ShareAlike 3.0 Unported License.