Hi,
Incoming calls from my ITSP are working and the calls hit my inbound route, and I can call between extensions, and terminate the call to an application such as an echo test, HOWEVER I cannot seem to get the extensions to ring for the incoming call. Here is a debug log. Can someone please tell me why FreePBX’s dial macros are not ringing my extension 9999?
This is an incoming call to my number (1780XXXXXXX) from a mobile phone. (1780YYYYYYY) numbers hidden to protect the innocent. 
If anyone can assist, I would really appreciate it as I cannot see from the debug log why it is happening. Someone more familiar with FreePBX would probably know.
Here is the SIP + Console debug of an inbound call:
<— SIP read from UDP:69.147.236.18:5060 —>
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 69.147.236.18;rport;branch=z9hG4bKUZyBQBa8c1UKj
Max-Forwards: 18
From: “THIRTYTWENTY” sip:[email protected];tag=SUSSy1mDc4K2D
To: sip:[email protected]
Call-ID: a5c89603-1490-1230-cea1-e5374ea19f81
CSeq: 27953058 INVITE
Contact: sip:[email protected]:5060
User-Agent: <My ITSP’s custom User Agent>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, precondition, path, replaces
Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 230
X-FS-Support: update_display,send_info
Remote-Party-ID: “THIRTYTWENTY” sip:[email protected];party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1336546296 1336546297 IN IP4 69.147— (18 headers 10 lines) —
== Using UDPTL TOS bits 184
Sending to 69.147.236.18:5060 (no NAT)
Using INVITE request as basis request - a5c89603-1490-1230-cea1-e5374ea19f81
Found peer ‘spout’ for ‘780YYYYYYY’ from 69.147.236.18:5060
== Using SIP RTP TOS bits 184
Found RTP audio format 0
Found RTP audio format 18
Found RTP audio format 101
Found audio description format telephone-event for ID 101
Capabilities: us - 0x4 (ulaw), peer - audio=0x104 (ulaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 69.147.236.18:31948
Looking for 1780XXXXXXX in from-trunk (domain 199.167.17.197)
list_route: hop: sip:[email protected]:5060
<— Transmitting (no NAT) to 69.147.236.18:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 69.147.236.18;branch=z9hG4bKUZyBQBa8c1UKj;received=69.147.236.18;rport=5060
From: “THIRTYTWENTY” sip:[email protected];tag=SUSSy1mDc4K2D
To: sip:[email protected]
Call-ID: a5c89603-1490-1230-cea1-e5374ea19f81
CSeq: 27953058 INVITE
Server: FPBX-2.10.0(1.8.9.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:[email protected]:5060
Content-Length: 0
<------------>
– Executing [1780XXXXXXX@from-trunk:1] Set(“SIP/spout-00000015”, “__FROM_DID=1780XXXXXXX”) in new stack
– Executing [1780XXXXXXX@from-trunk:2] Set(“SIP/spout-00000015”, “CDR(did)=1780XXXXXXX”) in new stack
– Executing [1780XXXXXXX@from-trunk:3] ExecIf(“SIP/spout-00000015”, “0 ?Set(CALLERID(name)=780YYYYYYY)”) in new stack
– Executing [1780XXXXXXX@from-trunk:4] Set(“SIP/spout-00000015”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
– Executing [1780XXXXXXX@from-trunk:5] Set(“SIP/spout-00000015”, “CALLERPRES()=allowed_not_screened”) in new stack
– Executing [1780XXXXXXX@from-trunk:6] Goto(“SIP/spout-00000015”, “from-did-direct,9999,1”) in new stack
– Goto (from-did-direct,9999,1)
– Executing [9999@from-did-direct:1] Set(“SIP/spout-00000015”, “__RINGTIMER=”) in new stack
– Executing [9999@from-did-direct:2] Macro(“SIP/spout-00000015”, “exten-vm,novm,9999,0,0,0”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“SIP/spout-00000015”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/spout-00000015”, “AMPUSER=780YYYYYYY”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/spout-00000015”, “0?report”) in new stack
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/spout-00000015”, “1?Set(REALCALLERIDNUM=780YYYYYYY)”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/spout-00000015”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/spout-00000015”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/spout-00000015”, “1?report”) in new stack
– Goto (macro-user-callerid,s,11)
– Executing [s@macro-user-callerid:11] GotoIf(“SIP/spout-00000015”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:12] Set(“SIP/spout-00000015”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:13] GotoIf(“SIP/spout-00000015”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,24)
– Executing [s@macro-user-callerid:24] Set(“SIP/spout-00000015”, “CALLERID(number)=780YYYYYYY”) in new stack
– Executing [s@macro-user-callerid:25] Set(“SIP/spout-00000015”, “CALLERID(name)=THIRTYTWENTY”) in new stack
– Executing [s@macro-user-callerid:26] Set(“SIP/spout-00000015”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-exten-vm:2] Set(“SIP/spout-00000015”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“SIP/spout-00000015”, “__EXTTOCALL=9999”) in new stack
– Executing [s@macro-exten-vm:4] Set(“SIP/spout-00000015”, “__PICKUPMARK=9999”) in new stack
– Executing [s@macro-exten-vm:5] Set(“SIP/spout-00000015”, “RT=”) in new stack
– Executing [s@macro-exten-vm:6] Gosub(“SIP/spout-00000015”, “sub-record-check,s,1(exten,9999,)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/spout-00000015”, “1?check”) in new stack
– Goto (sub-record-check,s,6)
– Executing [s@sub-record-check:6] Set(“SIP/spout-00000015”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:7] GotoIf(“SIP/spout-00000015”, “1?next”) in new stack
– Goto (sub-record-check,s,10)
– Executing [s@sub-record-check:10] ExecIf(“SIP/spout-00000015”, “0?Return()”) in new stack
– Executing [s@sub-record-check:11] GotoIf(“SIP/spout-00000015”, “0?exten,1”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/spout-00000015”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/spout-00000015”, “0?Set(__REC_POLICY_MODE=)”) in new stack
– Executing [s@sub-record-check:14] Set(“SIP/spout-00000015”, “NOW=1336578334”) in new stack
– Executing [s@sub-record-check:15] Set(“SIP/spout-00000015”, “__DAY=09”) in new stack
– Executing [s@sub-record-check:16] Set(“SIP/spout-00000015”, “__MONTH=05”) in new stack
– Executing [s@sub-record-check:17] Set(“SIP/spout-00000015”, “__YEAR=2012”) in new stack
– Executing [s@sub-record-check:18] Set(“SIP/spout-00000015”, “__TIMESTR=20120509-154534”) in new stack
– Executing [s@sub-record-check:19] Set(“SIP/spout-00000015”, “__FROMEXTEN=780YYYYYYY”) in new stack
– Executing [s@sub-record-check:20] Set(“SIP/spout-00000015”, “__CALLFILENAME=exten-9999-780YYYYYYY-20120509-154534-1336578334.21”) in new stack
– Executing [s@sub-record-check:21] Goto(“SIP/spout-00000015”, “exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] GotoIf(“SIP/spout-00000015”, “0?callee”) in new stack
– Executing [exten@sub-record-check:2] Set(“SIP/spout-00000015”, “__REC_POLICY_MODE=”) in new stack
– Executing [exten@sub-record-check:3] GotoIf(“SIP/spout-00000015”, “0?caller”) in new stack
– Executing [exten@sub-record-check:4] GotoIf(“SIP/spout-00000015”, “1?callee”) in new stack
– Goto (sub-record-check,exten,8)
– Executing [exten@sub-record-check:8] GosubIf(“SIP/spout-00000015”, “0?record,1(exten,9999,780YYYYYYY)”) in new stack
– Executing [exten@sub-record-check:9] Return(“SIP/spout-00000015”, “”) in new stack
– Executing [s@macro-exten-vm:7] Macro(“SIP/spout-00000015”, “dial-one,tr,9999”) in new stack
– Executing [s@macro-dial-one:1] Set(“SIP/spout-00000015”, “DEXTEN=9999”) in new stack
– Executing [s@macro-dial-one:2] Set(“SIP/spout-00000015”, “DIALSTATUS_CW=”) in new stack
– Executing [s@macro-dial-one:3] GosubIf(“SIP/spout-00000015”, “0?screen,1()”) in new stack
– Executing [s@macro-dial-one:4] GosubIf(“SIP/spout-00000015”, “0?cf,1()”) in new stack
– Goto (macro-dial-one,s,8)
– Goto (macro-dial-one,s,12)
== Spawn extension (macro-exten-vm, s-NOANSWER, 3) exited non-zero on ‘SIP/spout-00000015’ in macro ‘exten-vm’
== Spawn extension (from-did-direct, 9999, 2) exited non-zero on ‘SIP/spout-00000015’
– Executing [h@from-did-direct:1] Macro(“SIP/spout-00000015”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/spout-00000015”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,3)
– Executing [s@macro-hangupcall:3] Hangup(“SIP/spout-00000015”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/spout-00000015’ in macro ‘hangupcall’
== Spawn extension (from-did-direct, h, 1) exited non-zero on ‘SIP/spout-00000015’
Please note this is FreePBX latest (up to date) and Asterisk 1.8.9.3.
Can anyone identify this issue?