Inbound Caller gets Fast Busy and Extension gets ringing

Question

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

Did you read the [wiki article](https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions) that was linked in the warning message? — Michael Hampton, Aug 01 '12 at 17:25
Your post is excessively long the limit is 30K - please reduce your log 'snippet' to a sensible length as relevant information may have been lost from the end. — user9517, Aug 01 '12 at 17:26
It's well clear of the 30k limit which it lets you know as you post the message — MarkKGreenway, Aug 05 '12 at 16:27

score 2 · Answer 1 · answered Aug 01 '12 at 17:31

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.

Inbound Caller gets Fast Busy and Extension gets ringing

1 Answers1