Call does not go through

I am having some trouble receiving calls on my toll free line. This is a new asterisk PBX that I have configured. I have another trunk that receives incoming calls just fine, but this one is giving trouble. When I dial the 877 number from my cell phone, I see in asterisk that the call comes in and is router properly (the desk phone rings). Trouble is, when I pick up the desk phone…the cell phone still plays the ringing sound and does not show the call as connected. It does this indefinitely. When I log into my portal, I can see where I am billed for the call.

Any ideas on why the call isn’t going through? The log’s below:

-- Executing [19999994504@from-sip-external:1] NoOp("SIP/66.193.176.35-00000021", "Received incoming SIP connection from unknown peer to 19999994504") in new stack
-- Executing [19999994504@from-sip-external:2] Set("SIP/66.193.176.35-00000021", "DID=19999994504") in new stack
-- Executing [19999994504@from-sip-external:3] Goto("SIP/66.193.176.35-00000021", "s,1") in new stack
-- Goto (from-sip-external,s,1)
-- Executing [s@from-sip-external:1] GotoIf("SIP/66.193.176.35-00000021", "1?checklang:noanonymous") in new stack
-- Goto (from-sip-external,s,2)
-- Executing [s@from-sip-external:2] GotoIf("SIP/66.193.176.35-00000021", "0?setlanguage:from-trunk,19999994504,1") in new stack
-- Goto (from-trunk,19999994504,1)
-- Executing [19999994504@from-trunk:1] NoOp("SIP/66.193.176.35-00000021", "Catch-All DID Match - Found 19999994504 - You probably want a DID for this.") in new stack
-- Executing [19999994504@from-trunk:2] Goto("SIP/66.193.176.35-00000021", "ext-did,s,1") in new stack
-- Goto (ext-did,s,1)
-- Executing [s@ext-did:1] Set("SIP/66.193.176.35-00000021", "__FROM_DID=s") in new stack
-- Executing [s@ext-did:2] Gosub("SIP/66.193.176.35-00000021", "app-blacklist-check,s,1") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/66.193.176.35-00000021", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:2] Set("SIP/66.193.176.35-00000021", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:3] Return("SIP/66.193.176.35-00000021", "") in new stack
-- Executing [s@ext-did:3] ExecIf("SIP/66.193.176.35-00000021", "0 ?Set(CALLERID(name)=12515551212)") in new stack
-- Executing [s@ext-did:4] Set("SIP/66.193.176.35-00000021", "__CALLINGPRES_SV=allowed_not_screened") in new stack
-- Executing [s@ext-did:5] Set("SIP/66.193.176.35-00000021", "CALLERPRES()=allowed_not_screened") in new stack
-- Executing [s@ext-did:6] Goto("SIP/66.193.176.35-00000021", "from-did-direct,40,1") in new stack
-- Goto (from-did-direct,40,1)
-- Executing [40@from-did-direct:1] Macro("SIP/66.193.176.35-00000021", "exten-vm,novm,40") in new stack
-- Executing [s@macro-exten-vm:1] Macro("SIP/66.193.176.35-00000021", "user-callerid,") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/66.193.176.35-00000021", "AMPUSER=12515551212") in new stack
-- Executing [s@macro-user-callerid:2] GotoIf("SIP/66.193.176.35-00000021", "0?report") in new stack
-- Executing [s@macro-user-callerid:3] ExecIf("SIP/66.193.176.35-00000021", "1?Set(REALCALLERIDNUM=12515551212)") in new stack
-- Executing [s@macro-user-callerid:4] Set("SIP/66.193.176.35-00000021", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/66.193.176.35-00000021", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("SIP/66.193.176.35-00000021", "1?report") in new stack
-- Goto (macro-user-callerid,s,10)
-- Executing [s@macro-user-callerid:10] GotoIf("SIP/66.193.176.35-00000021", "0?continue") in new stack
-- Executing [s@macro-user-callerid:11] Set("SIP/66.193.176.35-00000021", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:12] GotoIf("SIP/66.193.176.35-00000021", "1?continue") in new stack
-- Goto (macro-user-callerid,s,19)
-- Executing [s@macro-user-callerid:19] Set("SIP/66.193.176.35-00000021", "CALLERID(number)=12515551212") in new stack
-- Executing [s@macro-user-callerid:20] Set("SIP/66.193.176.35-00000021", "CALLERID(name)=Cell Phone AL") in new stack
-- Executing [s@macro-user-callerid:21] NoOp("SIP/66.193.176.35-00000021", "Using CallerID "Cell Phone AL" <12515551212>") in new stack
-- Executing [s@macro-exten-vm:2] Set("SIP/66.193.176.35-00000021", "RingGroupMethod=none") in new stack
-- Executing [s@macro-exten-vm:3] Set("SIP/66.193.176.35-00000021", "VMBOX=novm") in new stack
-- Executing [s@macro-exten-vm:4] Set("SIP/66.193.176.35-00000021", "__EXTTOCALL=40") in new stack
-- Executing [s@macro-exten-vm:5] Set("SIP/66.193.176.35-00000021", "CFUEXT=") in new stack
-- Executing [s@macro-exten-vm:6] Set("SIP/66.193.176.35-00000021", "CFBEXT=") in new stack
-- Executing [s@macro-exten-vm:7] Set("SIP/66.193.176.35-00000021", "RT=""") in new stack
-- Executing [s@macro-exten-vm:8] Macro("SIP/66.193.176.35-00000021", "record-enable,40,IN") in new stack
-- Executing [s@macro-record-enable:1] GotoIf("SIP/66.193.176.35-00000021", "1?check") in new stack
-- Goto (macro-record-enable,s,4)
-- Executing [s@macro-record-enable:4] ExecIf("SIP/66.193.176.35-00000021", "0?MacroExit()") in new stack
-- Executing [s@macro-record-enable:5] GotoIf("SIP/66.193.176.35-00000021", "0?Group:OUT") in new stack
-- Goto (macro-record-enable,s,15)
-- Executing [s@macro-record-enable:15] GotoIf("SIP/66.193.176.35-00000021", "1?IN") in new stack
-- Goto (macro-record-enable,s,20)
-- Executing [s@macro-record-enable:20] ExecIf("SIP/66.193.176.35-00000021", "0?MacroExit()") in new stack
-- Executing [s@macro-record-enable:21] NoOp("SIP/66.193.176.35-00000021", "Recording enable for 40") in new stack
-- Executing [s@macro-record-enable:22] Set("SIP/66.193.176.35-00000021", "CALLFILENAME=20130902-213250-1378175570.37") in new stack
-- Executing [s@macro-record-enable:23] MixMonitor("SIP/66.193.176.35-00000021", "20130902-213250-1378175570.37.gsm,,") in new stack
-- Executing [s@macro-record-enable:24] Set("SIP/66.193.176.35-00000021", "CDR(userfield)=audio:20130902-213250-1378175570.37.gsm") in new stack
-- Executing [s@macro-record-enable:25] MacroExit("SIP/66.193.176.35-00000021", "") in new stack
-- Executing [s@macro-exten-vm:9] Macro("SIP/66.193.176.35-00000021", "dial-one,"",tr,40") in new stack
-- Executing [s@macro-dial-one:1] Set("SIP/66.193.176.35-00000021", "DEXTEN=40") in new stack
-- Executing [s@macro-dial-one:2] Set("SIP/66.193.176.35-00000021", "DIALSTATUS_CW=") in new stack
-- Executing [s@macro-dial-one:3] GosubIf("SIP/66.193.176.35-00000021", "0?screen,1") in new stack

== Begin MixMonitor Recording SIP/66.193.176.35-00000021
– Executing [s@macro-dial-one:4] GosubIf(“SIP/66.193.176.35-00000021”, “0?cf,1”) in new stack
– Executing [s@macro-dial-one:5] GotoIf(“SIP/66.193.176.35-00000021”, “1?skip1”) in new stack
– Goto (macro-dial-one,s,8)
– Executing [s@macro-dial-one:8] GotoIf(“SIP/66.193.176.35-00000021”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:9] GotoIf(“SIP/66.193.176.35-00000021”, “0?continue”) in new stack
– Executing [s@macro-dial-one:10] Set(“SIP/66.193.176.35-00000021”, “EXTHASCW=ENABLED”) in new stack
– Executing [s@macro-dial-one:11] GotoIf(“SIP/66.193.176.35-00000021”, “0?next1:cwinusebusy”) in new stack
– Goto (macro-dial-one,s,23)
– Executing [s@macro-dial-one:23] GotoIf(“SIP/66.193.176.35-00000021”, “1?next3:continue”) in new stack
– Goto (macro-dial-one,s,24)
– Executing [s@macro-dial-one:24] ExecIf(“SIP/66.193.176.35-00000021”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
– Executing [s@macro-dial-one:25] GotoIf(“SIP/66.193.176.35-00000021”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:26] GosubIf(“SIP/66.193.176.35-00000021”, “1?dstring,1:dlocal,1”) in new stack
– Executing [dstring@macro-dial-one:1] Set(“SIP/66.193.176.35-00000021”, “DSTRING=”) in new stack
– Executing [dstring@macro-dial-one:2] Set(“SIP/66.193.176.35-00000021”, “DEVICES=40”) in new stack
– Executing [dstring@macro-dial-one:3] ExecIf(“SIP/66.193.176.35-00000021”, “0?Return()”) in new stack
– Executing [dstring@macro-dial-one:4] ExecIf(“SIP/66.193.176.35-00000021”, “0?Set(DEVICES=0)”) in new stack
– Executing [dstring@macro-dial-one:5] Set(“SIP/66.193.176.35-00000021”, “LOOPCNT=1”) in new stack
– Executing [dstring@macro-dial-one:6] Set(“SIP/66.193.176.35-00000021”, “ITER=1”) in new stack
– Executing [dstring@macro-dial-one:7] Set(“SIP/66.193.176.35-00000021”, “THISDIAL=SIP/40”) in new stack
– Executing [dstring@macro-dial-one:8] GosubIf(“SIP/66.193.176.35-00000021”, “1?zap2dahdi,1”) in new stack
– Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/66.193.176.35-00000021”, “0?Return()”) in new stack
– Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/66.193.176.35-00000021”, “NEWDIAL=”) in new stack
– Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/66.193.176.35-00000021”, “LOOPCNT2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/66.193.176.35-00000021”, “ITER2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/66.193.176.35-00000021”, “THISPART2=SIP/40”) in new stack
– Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/66.193.176.35-00000021”, “0?Set(THISPART2=DAHDI/40)”) in new stack
– Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/66.193.176.35-00000021”, “NEWDIAL=SIP/40&”) in new stack
– Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/66.193.176.35-00000021”, “ITER2=2”) in new stack
– Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/66.193.176.35-00000021”, “0?begin2”) in new stack
– Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/66.193.176.35-00000021”, “THISDIAL=SIP/40”) in new stack
– Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/66.193.176.35-00000021”, “”) in new stack
– Executing [dstring@macro-dial-one:9] Set(“SIP/66.193.176.35-00000021”, “DSTRING=SIP/40&”) in new stack
– Executing [dstring@macro-dial-one:10] Set(“SIP/66.193.176.35-00000021”, “ITER=2”) in new stack
– Executing [dstring@macro-dial-one:11] GotoIf(“SIP/66.193.176.35-00000021”, “0?begin”) in new stack
– Executing [dstring@macro-dial-one:12] Set(“SIP/66.193.176.35-00000021”, “DSTRING=SIP/40”) in new stack
– Executing [dstring@macro-dial-one:13] Return(“SIP/66.193.176.35-00000021”, “”) in new stack
– Executing [s@macro-dial-one:27] GotoIf(“SIP/66.193.176.35-00000021”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:28] GotoIf(“SIP/66.193.176.35-00000021”, “1?skiptrace”) in new stack
– Goto (macro-dial-one,s,30)
– Executing [s@macro-dial-one:30] Set(“SIP/66.193.176.35-00000021”, “D_OPTIONS=tr”) in new stack
– Executing [s@macro-dial-one:31] ExecIf(“SIP/66.193.176.35-00000021”, “0?SIPAddHeader(Alert-Info: )”) in new stack
– Executing [s@macro-dial-one:32] ExecIf(“SIP/66.193.176.35-00000021”, “0?SIPAddHeader()”) in new stack
– Executing [s@macro-dial-one:33] ExecIf(“SIP/66.193.176.35-00000021”, “0?Set(CHANNEL(musicclass)=)”) in new stack
– Executing [s@macro-dial-one:34] GosubIf(“SIP/66.193.176.35-00000021”, “0?qwait,1”) in new stack
– Executing [s@macro-dial-one:35] Set(“SIP/66.193.176.35-00000021”, “__CWIGNORE=”) in new stack
– Executing [s@macro-dial-one:36] Set(“SIP/66.193.176.35-00000021”, “__KEEPCID=TRUE”) in new stack
– Executing [s@macro-dial-one:37] Dial(“SIP/66.193.176.35-00000021”, “SIP/40,”",tr") in new stack
== Using SIP VIDEO TOS bits 136
== Using SIP VIDEO CoS mark 6
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP/40
– SIP/40-00000022 is ringing
– SIP/40-00000022 answered SIP/66.193.176.35-00000021
> 0x7fc9504cab10 – Probation passed - setting RTP source address to 192.168.0.30:11784
– Executing [h@macro-dial-one:1] Macro(“SIP/66.193.176.35-00000021”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/66.193.176.35-00000021”, “0?endmixmoncheck”) in new stack
– Executing [s@macro-hangupcall:2] Set(“SIP/66.193.176.35-00000021”, “MIXMON_CALLFILENAME=/var/spool/asterisk/monitor/20130902-213250-1378175570.37.gsm”) in new stack
– Executing [s@macro-hangupcall:3] GotoIf(“SIP/66.193.176.35-00000021”, “1?defaultmixmondir”) in new stack
– Goto (macro-hangupcall,s,5)
– Executing [s@macro-hangupcall:5] System(“SIP/66.193.176.35-00000021”, “test -e /var/spool/asterisk/monitor/20130902-213250-1378175570.37.gsm”) in new stack
– Executing [s@macro-hangupcall:6] NoOp(“SIP/66.193.176.35-00000021”, “SYSTEMSTATUS = SUCCESS”) in new stack
– Executing [s@macro-hangupcall:7] GotoIf(“SIP/66.193.176.35-00000021”, “1?endmixmoncheck”) in new stack
– Goto (macro-hangupcall,s,9)
– Executing [s@macro-hangupcall:9] NoOp(“SIP/66.193.176.35-00000021”, “End of MIXMON check”) in new stack
– Executing [s@macro-hangupcall:10] GotoIf(“SIP/66.193.176.35-00000021”, “1?nomeetmemon”) in new stack
– Goto (macro-hangupcall,s,28)
– Executing [s@macro-hangupcall:28] NoOp(“SIP/66.193.176.35-00000021”, “End of MEETME check”) in new stack
– Executing [s@macro-hangupcall:29] GotoIf(“SIP/66.193.176.35-00000021”, “1?noautomon”) in new stack
– Goto (macro-hangupcall,s,34)
– Executing [s@macro-hangupcall:34] NoOp(“SIP/66.193.176.35-00000021”, “TOUCH_MONITOR_OUTPUT=”) in new stack
– Executing [s@macro-hangupcall:35] GotoIf(“SIP/66.193.176.35-00000021”, “1?noautomon2”) in new stack
– Goto (macro-hangupcall,s,41)
– Executing [s@macro-hangupcall:41] NoOp(“SIP/66.193.176.35-00000021”, “MONITOR_FILENAME=”) in new stack
– Executing [s@macro-hangupcall:42] GotoIf(“SIP/66.193.176.35-00000021”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,45)
– Executing [s@macro-hangupcall:45] GotoIf(“SIP/66.193.176.35-00000021”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,48)
– Executing [s@macro-hangupcall:48] GotoIf(“SIP/66.193.176.35-00000021”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,50)
– Executing [s@macro-hangupcall:50] AGI(“SIP/66.193.176.35-00000021”, “hangup.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/hangup.agi
– <SIP/66.193.176.35-00000021>AGI Script hangup.agi completed, returning 0
– Executing [s@macro-hangupcall:51] Hangup(“SIP/66.193.176.35-00000021”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 51) exited non-zero on ‘SIP/66.193.176.35-00000021’ in macro ‘hangupcall’
== Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/66.193.176.35-00000021’
== Spawn extension (macro-dial-one, s, 37) exited non-zero on ‘SIP/66.193.176.35-00000021’ in macro ‘dial-one’
== Spawn extension (macro-exten-vm, s, 9) exited non-zero on ‘SIP/66.193.176.35-00000021’ in macro ‘exten-vm’
== Spawn extension (from-did-direct, 40, 1) exited non-zero on ‘SIP/66.193.176.35-00000021’
== MixMonitor close filestream (mixed)
== End MixMonitor Recording SIP/66.193.176.35-00000021

Nevermind! I posted this same message to my SIP provider (Callcentric) and they replied within minutes with the following message. Never expected my trunk provider to give this kind of support, which is awesome. And it fixed the problem!

Hello,

We have sent a test call towards your number 1877555555 and we are showing the following on our trace:

SIP/2.0 200 OK
Via: SIP/2.0/UDP 204.11.192.171:5060;branch=z9hG4bK-5a3e93ce211c19d4fe3e92def9652ba6;received=204.11.192.171;rport=5060
From: “CALLCENTRIC” sip:[email protected];tag=3587165226-817307
To: sip:[email protected];tag=as6200eec9
Call-ID: [email protected]
CSeq: 1 INVITE
Server: FPBX-2.8.1(11.4.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:[email protected]:5060
Content-Type: application/sdp
Require: timer
Content-Length: 304

v=0
o=root 1420409399 1420409399 IN IP4 192.168.0.6
s=Asterisk PBX 11.4.0
c=IN IP4 192.168.0.6
t=0 0
m=audio 15662 RTP/AVP 8 18 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

The following is the 200OK packet being sent from your PBX. What we find very peculiar about the 200OK packet your PBX is sending back is that your PBX is sending back the header “Require: timer” on the 200OK packet; which we strongly believe is causing your incoming calls to not establish properly. Please note that this header isn’t necessary to establish the call, and we recommend that you configure your PBX to not send that header.

If you would, within your sip_general_custom.conf file, can you add the line “session-timers=refuse”. Once you have added the line above, please restart the entire Asterisk process in order for the change to take into effect.

If you have any other questions, please let us know.

You can actually fix this by putting session-timers=refuse in the PEER details of your Callcentric trunk.

By putting it into the sip_general_custom.conf, you’ll be affecting all of your trunks. By putting it into your Callcentric trunk settings, it will only affect your Callcentric trunk.