Can't Call Out And Don't Know How to Read the Logs. Please Help!

General Help
1

I’m a newbie and have no clue what I am looking at in these logs. But I figured out how to get them. Can some one please help me identify the problem in my setup? And I don’t have a clue what 99.7.231.29 is.

<--- SIP read from UDP:99.7.231.29:42743 --->
INVITE sip:[email protected];transport=UDP SIP/2.0
Via: SIP/2.0/UDP 99.7.231.29:42743;branch=z9hG4bK-d8754z-b8c51dc8b0d775ae-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:[email protected]:42743;transport=UDP>
To: <sip:[email protected];transport=UDP>
From: "9045352288"<sip:[email protected];transport=UDP>;tag=f9f37a21
Call-ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri
User-Agent: Zoiper r21367
Authorization: Digest username="818",realm="asterisk",nonce="1ffe6074",uri="sip:[email protected];transport=UDP",response="22726b1854dc831c7b394c9946419a4d",algorithm=MD5
Allow-Events: presence, kpml
Content-Length: 162

v=0
o=Z 0 0 IN IP4 99.7.231.29
s=Z
c=IN IP4 99.7.231.29
t=0 0
m=audio 37520 RTP/AVP 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
<------------->
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  0 [ 70]: INVITE sip:[email protected];transport=UDP SIP/2.0
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  1 [ 91]: Via: SIP/2.0/UDP 99.7.231.29:42743;branch=z9hG4bK-d8754z-b8c51dc8b0d775ae-1---d8754z-;rport
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  2 [ 16]: Max-Forwards: 70
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  3 [ 50]: Contact: <sip:[email protected]:42743;transport=UDP>
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  4 [ 61]: To: <sip:[email protected];transport=UDP>
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  5 [ 79]: From: "9045352288"<sip:[email protected];transport=UDP>;tag=f9f37a21
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  6 [ 53]: Call-ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  7 [ 14]: CSeq: 2 INVITE
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  8 [ 81]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header  9 [ 29]: Content-Type: application/sdp
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header 10 [ 74]: Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header 11 [ 25]: User-Agent: Zoiper r21367
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header 12 [190]: Authorization: Digest username="818",realm="asterisk",nonce="1ffe6074",uri="sip:[email protected];transport=UDP",response="22726b1854dc831c7b394c9946419a4d",algorithm=MD5
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header 13 [ 28]: Allow-Events: presence, kpml
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header 14 [ 19]: Content-Length: 162
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:  Header 15 [  0]:
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  0 [  3]: v=0
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  1 [ 26]: o=Z 0 0 IN IP4 99.7.231.29
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  2 [  3]: s=Z
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  3 [ 20]: c=IN IP4 99.7.231.29
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  4 [  5]: t=0 0
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  5 [ 29]: m=audio 37520 RTP/AVP 8 0 101
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  6 [ 33]: a=rtpmap:101 telephone-event/8000
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  7 [ 15]: a=fmtp:101 0-15
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c:    Body  8 [ 10]: a=sendrecv
[2015-01-24 18:30:00] VERBOSE[25852] chan_sip.c: --- (15 headers 9 lines) ---
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: = Looking for  Call ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE. (Checking From) --From tag f9f37a21 --To-tag
[2015-01-24 18:30:00] DEBUG[25852] netsock2.c: Splitting 'phone.cocobelladolls.com' into...
[2015-01-24 18:30:00] DEBUG[25852] netsock2.c: ...host 'phone.cocobelladolls.com' and port ''.
[2015-01-24 18:30:00] DEBUG[25852] netsock2.c: Splitting 'phone.cocobelladolls.com' into...
[2015-01-24 18:30:00] DEBUG[25852] netsock2.c: ...host 'phone.cocobelladolls.com' and port ''.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: Splitting '99.7.231.29:42743' into...
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: ...host '99.7.231.29' and port '42743'.
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Sending to 99.7.231.29:42743 (NAT)
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Using INVITE request as basis request - YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: Splitting 'phone.cocobelladolls.com' into...
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: ...host 'phone.cocobelladolls.com' and port ''.
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Found peer '818' for '818' from 99.7.231.29:42743
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f6208034ba8'
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] res_rtp_asterisk.c: Allocated port 12830 for RTP instance '0x7f6208034ba8'
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: Splitting '172.31.50.253' into...
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: ...host '172.31.50.253' and port ''.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: RTP instance '0x7f6208034ba8' is setup and ready to go
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f6208034ba8'
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] netsock2.c:   == Using SIP RTP TOS bits 184
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] netsock2.c:   == Using SIP RTP CoS mark 5
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Setting NAT on RTP to On
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing session-level SDP o=Z 0 0 IN IP4 99.7.231.29... OK.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing session-level SDP s=Z... UNSUPPORTED OR FAILED.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: Splitting '99.7.231.29' into...
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: ...host '99.7.231.29' and port ''.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 99.7.231.29... OK.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Found RTP audio format 8
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0x7f61d67ecc00
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Found RTP audio format 0
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0x7f61d67ecc00
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Found RTP audio format 101
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Setting payload 101 based on m type on 0x7f61d67ecc00
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Found audio description format telephone-event for ID 101
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Capabilities: us - (ulaw|alaw|g729|g722), peer - audio=(ulaw|alaw)/video=(nothing)/text=(nothing), combined - (ulaw|alaw)
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6208034ba8'
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Peer audio RTP is at port 99.7.231.29:37520
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Copying payload 0 from 0x7f61d67ecc00 to 0x7f6208034d70
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Copying payload 8 from 0x7f61d67ecc00 to 0x7f6208034d70
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] rtp_engine.c: Copying payload 101 from 0x7f61d67ecc00 to 0x7f6208034d70
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f6208034ba8'
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: We're settling with these formats: (ulaw|alaw)
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Checking SIP call limits for device 818
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Updating call counter for incoming call
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Call from peer '818' is 1 out of 2147483647
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: No provider found, checking channel drivers for SIP - 818
[2015-01-24 18:30:00] DEBUG[25837] chan_sip.c: Checking device state for peer 818
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: Changing state for SIP/818 - state 2 (In use)
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: device 'SIP/818' state '2'
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking if I can find provider for "Custom" - number: DND818
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking provider Custom with Custom
[2015-01-24 18:30:00] DEBUG[25839] db.c: Unable to find key 'DND818' in family 'CustomDevstate'
[2015-01-24 18:30:00] DEBUG[25839] app_queue.c: Extension '818@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2015-01-24 18:30:00] DEBUG[25882] app_queue.c: Device 'SIP/818' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: Splitting 'phone.cocobelladolls.com' into...
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: ...host 'phone.cocobelladolls.com' and port ''.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: Splitting 'phone.cocobelladolls.com' into...
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] netsock2.c: ...host 'phone.cocobelladolls.com' and port ''.
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: Looking for +18506273471 in from-internal (domain phone.cocobelladolls.com)
[2015-01-24 18:30:00] DEBUG[25829] res_odbc.c: odbc_release_obj2(0x21be8a8) called (obj->txf = (nil))
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: *** Our native formats are (ulaw)
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw|alaw)
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: *** Our capabilities are (ulaw|alaw|g729|g722)
2

Your log stopped at the interesting bit for call 25852, post the issue of:-

grep “VERBOSE[25852]” /var/log/asterisk/full

3

[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: This channel will not be able to handle video.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: build_route: Contact hop: sip:[email protected]:42743;transport=UDP
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c: list_route: hop: sip:[email protected]:42743;transport=UDP
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: SIP/818-00000000: New call is still down… Trying…
[2015-01-24 18:30:00] VERBOSE[25852][C-00000000] chan_sip.c:
<— Transmitting (NAT) to 99.7.231.29:42743 —>
SIP/2.0 100 Trying^M
Via: SIP/2.0/UDP 99.7.231.29:42743;branch=z9hG4bK-d8754z-b8c51dc8b0d775ae-1—d8754z-;received=99.7.231.29;rport=42743^M
From: "9045352288"sip:[email protected];transport=UDP;tag=f9f37a21^M
To: sip:[email protected];transport=UDP^M
Call-ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.^M
CSeq: 2 INVITE^M
Server: FPBX-2.11.0(11.2.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH^M
Supported: replaces, timer^M
Contact: sip:[email protected]:5060^M
Content-Length: 0^M
^M

<------------>
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Trying to put ‘SIP/2.0 100’ onto UDP socket destined for 99.7.231.29:42743
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: No provider found, checking channel drivers for SIP - 818
[2015-01-24 18:30:00] DEBUG[25837] chan_sip.c: Checking device state for peer 818
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: Changing state for SIP/818 - state 2 (In use)
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: device ‘SIP/818’ state ‘2’
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking if I can find provider for “Custom” - number: DND818
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking provider Custom with Custom
[2015-01-24 18:30:00] DEBUG[25839] db.c: Unable to find key ‘DND818’ in family ‘CustomDevstate’
[2015-01-24 18:30:00] DEBUG[25882] app_queue.c: Device ‘SIP/818’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] logger.c: Call_ID [C-00000000] being removed from thread.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Macro’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [+18506273471@from-internal:1] Macro(“SIP/818-00000000”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘UNIQUEID’ is ‘1422124200.0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/818-00000000”, “TOUCH_MONITOR=1422124200.0”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is NULL
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘1’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is NULL
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/818-00000000”, “AMPUSER=818”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘CHANNEL’ (from ‘CHANNEL}’ len 7)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘CHANNEL’ is ‘SIP/818-00000000’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSERCIDNAME’ is NULL
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GotoIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/818-00000000”, “0?report”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Not taking any branch
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GotoIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘REALCALLERIDNUM’ is NULL
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘1’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘ExecIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/818-00000000”, “1?Set(REALCALLERIDNUM=818)”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: ExecIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: ExecIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘REALCALLERIDNUM:1:2’ (from ‘REALCALLERIDNUM:1:2}" = “”’ len 19)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘REALCALLERIDNUM’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘CALLERID(number)’ (from ‘CALLERID(number)})’ len 16)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘REALCALLERIDNUM’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/818-00000000”, “AMPUSER=818”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GotoIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/818-00000000”, “0?limit”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Not taking any branch
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GotoIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘Rufus Peoples’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:7] Set(“SIP/818-00000000”, “AMPUSERCIDNAME=Rufus Peoples”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSERCIDNAME’ is ‘Rufus Peoples’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GotoIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:8] GotoIf(“SIP/818-00000000”, “0?report”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Not taking any branch
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GotoIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘EXTERNAL’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘1’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘DB_RESULT’ is ‘9045352288’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:9] Set(“SIP/818-00000000”, “AMPUSERCID=818”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] db.c: Unable to find key ‘818/dialopts’ in family ‘AMPUSER’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘DB_RESULT’ is ‘9045352288’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘DIAL_OPTIONS’ is ‘Ttr’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘Ttr’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:10] Set(“SIP/818-00000000”, “__DIAL_OPTIONS=Ttr”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSERCIDNAME’ is ‘Rufus Peoples’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSERCID’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:11] Set(“SIP/818-00000000”, “CALLERID(all)=“Rufus Peoples” <818>”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘LIMIT’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘3’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GotoIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:12] GotoIf(“SIP/818-00000000”, “0?limit”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Not taking any branch
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GotoIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘LIMIT’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘3’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘1’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘ExecIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:13] ExecIf(“SIP/818-00000000”, “1?Set(GROUP(concurrency_limit)=818)”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: ExecIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘ARG1’ (from ‘ARG1}"=“LIMIT” & ${LEN(${AMPUSER})}’ len 4)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘LIMIT’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘LEN(${AMPUSER})’ (from ‘LEN(${AMPUSER})}’ len 15)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘AMPUSER’ (from ‘AMPUSER})’ len 7)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘3’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘1’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘AMPUSER’ (from ‘AMPUSER})’ len 7)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘generic’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘7’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘generic’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘7’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘MACRO_CONTEXT’ is ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GosubIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:14] GosubIf(“SIP/818-00000000”, “7?sub-ccss,s,1(from-internal,+18506273471)”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_stack.c: Channel SIP/818-00000000 has no datastore, so we’re allocating one.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_stack.c: Setting ‘ARG1’ to ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_stack.c: Setting ‘ARG2’ to ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GosubIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘LEN(${DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)})’ (from ‘LEN(${DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)})} & “${DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)}” != “never”’ len 51)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)’ (from ‘DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)})’ len 43)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘AMPUSER’ (from ‘AMPUSER}/ccss/cc_agent_policy)’ len 7)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘generic’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘7’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)’ (from ‘DB(AMPUSER/${AMPUSER}/ccss/cc_agent_policy)}" != “never”’ len 43)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘AMPUSER’ (from ‘AMPUSER}/ccss/cc_agent_policy)’ len 7)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘AMPUSER’ is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘generic’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘7’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘MACRO_CONTEXT’ (from ‘MACRO_CONTEXT},${CALLERID(dnid)})’ len 13)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘MACRO_CONTEXT’ is ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘CALLERID(dnid)’ (from ‘CALLERID(dnid)})’ len 14)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Incrementing gosub_level
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘CCSS_SETUP’ is NULL
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘ExecIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@sub-ccss:1] ExecIf(“SIP/818-00000000”, “0?Return()”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: ExecIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘LEN(${CCSS_SETUP})’ (from ‘LEN(${CCSS_SETUP})}’ len 18)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘CCSS_SETUP’ (from ‘CCSS_SETUP})’ len 10)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘CCSS_SETUP’ is NULL
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@sub-ccss:2] Set(“SIP/818-00000000”, “CCSS_SETUP=TRUE”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] db.c: Unable to find key ‘+18506273471/ccss/cc_monitor_policy’ in family ‘AMPUSER’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] func_db.c: DB: AMPUSER/+18506273471/ccss/cc_monitor_policy not found in database.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GosubIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@sub-ccss:3] GosubIf(“SIP/818-00000000”, “0?monitor_config,1(from-internal,+18506273471):monitor_default,1(from-internal,+18506273471)”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_stack.c: Setting ‘ARG1’ to ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_stack.c: Setting ‘ARG2’ to ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GosubIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘LEN(${DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)})’ (from ‘LEN(${DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)})}’ len 50)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)’ (from ‘DB(AMPUSER/${ARG2}/ccss/cc_monitor_policy)})’ len 42)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘ARG2’ (from ‘ARG2}/ccss/cc_monitor_policy)’ len 4)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] db.c: Unable to find key ‘+18506273471/ccss/cc_monitor_policy’ in family ‘AMPUSER’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] func_db.c: DB: AMPUSER/+18506273471/ccss/cc_monitor_policy not found in database.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘ARG1’ (from ‘ARG1},${ARG2}):monitor_default,1(${ARG1},${ARG2})’ len 4)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘ARG2’ (from ‘ARG2}):monitor_default,1(${ARG1},${ARG2})’ len 4)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘ARG1’ (from ‘ARG1},${ARG2})’ len 4)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘from-internal’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘ARG2’ (from ‘ARG2})’ len 4)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG2’ is ‘+18506273471’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] db.c: Unable to find key ‘+18506273471/cidname’ in family ‘AMPUSER’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] func_db.c: DB: AMPUSER/+18506273471/cidname not found in database.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘0’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GotoIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/818-00000000”, “0?is_exten”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Not taking any branch
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GotoIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘StackPop’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [monitor_default@sub-ccss:2] StackPop(“SIP/818-00000000”, “”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: StackPop
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Decrementing gosub_level
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Return’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [monitor_default@sub-ccss:3] Return(“SIP/818-00000000”, “FALSE”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Return
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Decrementing gosub_level
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘LIMIT’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Result of ‘ARG1’ is ‘LIMIT’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Expression result is ‘1’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘GotoIf’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/818-00000000”, “1?continue”) in new stack
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Goto (macro-user-callerid,s,28)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: GotoIf
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/818-00000000”, “CALLERID(number)=818”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘Rufus Peoples’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/818-00000000”, “CALLERID(name)=Rufus Peoples”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘818’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/818-00000000”, “CDR(cnum)=818”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘Rufus Peoples’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/818-00000000”, “CDR(cnam)=Rufus Peoples”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Evaluating ‘CHANNEL(language)’ (from ‘CHANNEL(language)}’ len 17)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘en’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Function result is ‘en’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Set’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/818-00000000”, “CHANNEL(language)=en”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] app_macro.c: Executed application: Set
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Auto fallthrough, channel ‘SIP/818-00000000’ status is ‘UNKNOWN’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] channel.c: Soft-Hanging up channel ‘SIP/818-00000000’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] channel.c: Soft-Hanging up channel ‘SIP/818-00000000’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Launching ‘Hangup’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: – Executing [h@from-internal:1] Hangup(“SIP/818-00000000”, “”) in new stack
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] channel.c: Soft-Hanging up channel ‘SIP/818-00000000’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on ‘SIP/818-00000000’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/818-00000000’
[2015-01-24 18:30:00] DEBUG[25829] res_odbc.c: odbc_release_obj2(0x21be8a8) called (obj->txf = (nil))
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] channel.c: Hanging up channel ‘SIP/818-00000000’
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: Hangup call SIP/818-00000000, SIP callid YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: update_call_counter(818) - decrement call limit counter on hangup
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: Updating call counter for incoming call
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: Call from peer ‘818’ removed from call limit 2147483647
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: No provider found, checking channel drivers for SIP - 818
[2015-01-24 18:30:00] DEBUG[25837] chan_sip.c: Checking device state for peer 818
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: Changing state for SIP/818 - state 1 (Not in use)
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: device ‘SIP/818’ state ‘1’
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking if I can find provider for “Custom” - number: DND818
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking provider Custom with Custom
[2015-01-24 18:30:00] DEBUG[25839] db.c: Unable to find key ‘DND818’ in family ‘CustomDevstate’
[2015-01-24 18:30:00] DEBUG[25839] app_queue.c: Extension ‘818@ext-local’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2015-01-24 18:30:00] DEBUG[25882] app_queue.c: Device ‘SIP/818’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: Hanging up channel in state Ring (not UP)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7f6208034ba8’
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog ‘YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.’ in 32000 ms (Method: INVITE)
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: AST hangup cause 16 (no match found in SIP)
[2015-01-24 18:30:00] VERBOSE[25996][C-00000000] chan_sip.c:
<— Reliably Transmitting (NAT) to 99.7.231.29:42743 —>
SIP/2.0 603 Declined^M
Via: SIP/2.0/UDP 99.7.231.29:42743;branch=z9hG4bK-d8754z-b8c51dc8b0d775ae-1—d8754z-;received=99.7.231.29;rport=42743^M
From: "9045352288"sip:[email protected];transport=UDP;tag=f9f37a21^M
To: sip:[email protected];transport=UDP;tag=as24a9b2e0^M
Call-ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.^M
CSeq: 2 INVITE^M
Server: FPBX-2.11.0(11.2.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH^M
Supported: replaces, timer^M
Content-Length: 0^M
^M

<------------>
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #40
[2015-01-24 18:30:00] DEBUG[25996][C-00000000] chan_sip.c: Trying to put ‘SIP/2.0 603’ onto UDP socket destined for 99.7.231.29:42743
[2015-01-24 18:30:00] DEBUG[25829] res_odbc.c: odbc_release_obj2(0x21be8a8) called (obj->txf = (nil))
[2015-01-24 18:30:00] DEBUG[25829] res_odbc.c: odbc_release_obj2(0x21be8a8) called (obj->txf = (nil))
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: No provider found, checking channel drivers for SIP - 818
[2015-01-24 18:30:00] DEBUG[25837] chan_sip.c: Checking device state for peer 818
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: Changing state for SIP/818 - state 1 (Not in use)
[2015-01-24 18:30:00] DEBUG[25837] devicestate.c: device ‘SIP/818’ state ‘1’
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking if I can find provider for “Custom” - number: DND818
[2015-01-24 18:30:00] DEBUG[25839] devicestate.c: Checking provider Custom with Custom
[2015-01-24 18:30:00] DEBUG[25839] db.c: Unable to find key ‘DND818’ in family ‘CustomDevstate’
[2015-01-24 18:30:00] DEBUG[25882] app_queue.c: Device ‘SIP/818’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2015-01-24 18:30:00] VERBOSE[25852] chan_sip.c:
<— SIP read from UDP:99.7.231.29:42743 —>
ACK sip:[email protected];transport=UDP SIP/2.0
Via: SIP/2.0/UDP 99.7.231.29:42743;branch=z9hG4bK-d8754z-b8c51dc8b0d775ae-1—d8754z-;rport
Max-Forwards: 70
To: sip:[email protected];transport=UDP;tag=as24a9b2e0
From: "9045352288"sip:[email protected];transport=UDP;tag=f9f37a21
Call-ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
CSeq: 2 ACK
Content-Length: 0

4

<------------->
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 0 [ 67]: ACK sip:[email protected];transport=UDP SIP/2.0
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 99.7.231.29:42743;branch=z9hG4bK-d8754z-b8c51dc8b0d775ae-1—d8754z-;rport
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 3 [ 76]: To: sip:[email protected];transport=UDP;tag=as24a9b2e0
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 4 [ 79]: From: "9045352288"sip:[email protected];transport=UDP;tag=f9f37a21
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 5 [ 53]: Call-ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 6 [ 11]: CSeq: 2 ACK
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: Header 7 [ 17]: Content-Length: 0
[2015-01-24 18:30:00] VERBOSE[25852] chan_sip.c: — (8 headers 0 lines) —
[2015-01-24 18:30:00] DEBUG[25852] chan_sip.c: = Looking for Call ID: YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE. (Checking From) --From tag f9f37a21 --To-tag as24a9b2e0
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread.
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #40
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] chan_sip.c: Stopping retransmission on ‘YTQ5OTk1YzFlZDcwNWM1ODI2Zjk0MTVmNTkxOTk0OGE.’ of Response 2: Match Found
[2015-01-24 18:30:00] DEBUG[25852][C-00000000] logger.c: Call_ID [C-00000000] being removed from thread.
[2015-01-24 18:30:01] DEBUG[25868] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2015-01-24 18:30:02] DEBUG[25868] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead
[2015-01-24 18:30:02] DEBUG[25868] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead
[2015-01-24 18:30:02] DEBUG[25868] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead
[2015-01-24 18:30:02] DEBUG[25868] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead
[2015-01-24 18:30:02] DEBUG[25868] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2015-01-24 18:30:09] DEBUG[25860] chan_iax2.c: ip callno count incremented to 13 for 127.0.0.1
[2015-01-24 18:30:09] DEBUG[25861] chan_iax2.c: ip callno count incremented to 14 for 127.0.0.1
[2015-01-24 18:30:09] DEBUG[25862] chan_iax2.c: ip callno count incremented to 15 for 127.0.0.1
[2015-01-24 18:30:09] DEBUG[25863] chan_iax2.c: ip callno count incremented to 16 for 127.0.0.1
[2015-01-24 18:30:17] VERBOSE[25936] asterisk.c: – Remote UNIX connection disconnected
[2015-01-24 18:30:19] DEBUG[25859] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[2015-01-24 18:30:19] DEBUG[25861] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[2015-01-24 18:30:19] DEBUG[25863] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[2015-01-24 18:30:19] DEBUG[25865] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds
[2015-01-24 18:30:19] DEBUG[25857] chan_iax2.c: ip callno count decremented to 15 for 127.0.0.1
[2015-01-24 18:30:19] DEBUG[25857] chan_iax2.c: ip callno count decremented to 14 for 127.0.0.1
[2015-01-24 18:30:19] DEBUG[25857] chan_iax2.c: ip callno count decremented to 13 for 127.0.0.1
[2015-01-24 18:30:19] DEBUG[25857] chan_iax2.c: ip callno count decremented to 12 for 127.0.0.1
[2015-01-24 18:30:21] DEBUG[25852] chan_sip.c: Auto destroying SIP dialog ‘NjVlN2I0ZTIyMzU4OTRkNjIwMDlhNDQyZmUxZTBkMmI.’
[2015-01-24 18:30:21] DEBUG[25852] chan_sip.c: Destroying SIP dialog NjVlN2I0ZTIyMzU4OTRkNjIwMDlhNDQyZmUxZTBkMmI.

5

I appended the rest of the logs. It was cut off due to size constraints. I will try the grep now.

6

I apologise for my formatting, you need to escape the [ and ]

grep "VERBOSE\[25852\]" /var/log/asterisk/full
7

Here is what the logs look like now after some tinkering:
[2015-01-25 00:50:54] VERBOSE[8018] chan_sip.c: — (8 headers 0 lines) —
[2015-01-25 00:50:54] VERBOSE[8018] chan_sip.c:
[2015-01-25 00:50:54] VERBOSE[8018] chan_sip.c: — (14 headers 13 lines) —
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Sending to 99.7.231.29:58911 (NAT)
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Using INVITE request as basis request - 3tEV3YHUqjTZPpHJl8aX47wCajAs6PxP
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found peer ‘818’ for ‘818’ from 99.7.231.29:58911
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] netsock2.c: == Using SIP RTP TOS bits 184
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found RTP audio format 8
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found RTP audio format 0
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found RTP audio format 101
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found audio description format PCMA for ID 8
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found audio description format PCMU for ID 0
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Found audio description format telephone-event for ID 101
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Capabilities: us - (ulaw|alaw|g729|g722), peer - audio=(ulaw|alaw)/video=(nothing)/text=(nothing), combined - (ulaw|alaw)
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Peer audio RTP is at port 99.7.231.29:50270
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: Looking for +12404861200 in from-internal (domain phone.cocobelladolls.com)
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c: list_route: hop: sip:[email protected]:58911
[2015-01-25 00:50:54] VERBOSE[8018][C-00000000] chan_sip.c:
[2015-01-25 00:50:55] VERBOSE[8018] chan_sip.c:
[2015-01-25 00:50:55] VERBOSE[8018] chan_sip.c: — (8 headers 0 lines) —
[2015-01-25 00:51:13] VERBOSE[8018] chan_sip.c:
[2015-01-25 00:51:16] VERBOSE[8018] chan_sip.c: Really destroying SIP dialog ‘85LQ-tbsQxcyYbi.IKuVOM7kh3MhEgAL’ Method: REGISTER
[2015-01-25 00:51:26] VERBOSE[8018] chan_sip.c: Really destroying SIP dialog ‘3tEV3YHUqjTZPpHJl8aX47wCajAs6PxP’ Method: ACK

8

Well, still missing stuff, start over with

core set debug off
core set verbose 3

and post another call, do you have an outbound route set that matches +12404861200 ?

9

I will do that now. This is my issue. I am trying to call out form 9045352288 to an outside line 2404861200. The 240 number is a standard cell phone

10

[2015-01-25 02:02:31] VERBOSE[8018][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184
[2015-01-25 02:02:31] VERBOSE[8018][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5
[2015-01-25 02:02:31] VERBOSE[6617][C-00000001] pbx.c: – Executing [+12404861200@from-internal:1] Macro(“SIP/818-00000001”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2015-01-25 02:02:31] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/818-00000001”, “TOUCH_MONITOR=1422151351.1”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/818-00000001”, “AMPUSER=818”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/818-00000001”, “0?report”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/818-00000001”, “1?Set(REALCALLERIDNUM=818)”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/818-00000001”, “AMPUSER=818”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/818-00000001”, “0?limit”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:7] Set(“SIP/818-00000001”, “AMPUSERCIDNAME=Rufus Peoples”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:8] GotoIf(“SIP/818-00000001”, “0?report”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:9] Set(“SIP/818-00000001”, “AMPUSERCID=818”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:10] Set(“SIP/818-00000001”, “__DIAL_OPTIONS=Ttr”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:11] Set(“SIP/818-00000001”, “CALLERID(all)=“Rufus Peoples” <818>”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:12] GotoIf(“SIP/818-00000001”, “0?limit”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:13] ExecIf(“SIP/818-00000001”, “1?Set(GROUP(concurrency_limit)=818)”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:14] GosubIf(“SIP/818-00000001”, “7?sub-ccss,s,1(from-internal,+12404861200)”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@sub-ccss:1] ExecIf(“SIP/818-00000001”, “0?Return()”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@sub-ccss:2] Set(“SIP/818-00000001”, “CCSS_SETUP=TRUE”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@sub-ccss:3] GosubIf(“SIP/818-00000001”, “0?monitor_config,1(from-internal,+12404861200):monitor_default,1(from-internal,+12404861200)”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/818-00000001”, “0?is_exten”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [monitor_default@sub-ccss:2] StackPop(“SIP/818-00000001”, “”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [monitor_default@sub-ccss:3] Return(“SIP/818-00000001”, “FALSE”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/818-00000001”, “1?continue”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Goto (macro-user-callerid,s,28)
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/818-00000001”, “CALLERID(number)=818”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/818-00000001”, “CALLERID(name)=Rufus Peoples”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/818-00000001”, “CDR(cnum)=818”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/818-00000001”, “CDR(cnam)=Rufus Peoples”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/818-00000001”, “CHANNEL(language)=en”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Auto fallthrough, channel ‘SIP/818-00000001’ status is ‘UNKNOWN’
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: – Executing [h@from-internal:1] Hangup(“SIP/818-00000001”, “”) in new stack
[2015-01-25 02:02:34] VERBOSE[6617][C-00000001] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/818-00000001’
[2015-01-25 02:03:10] VERBOSE[5557] asterisk.c: – Remote UNIX connection disconnected

11

I have a Google Voice Motif configured for 9045352288 and an outbound route for this

12

Ah!! Google, sorry but that is a best a hit-or-miss matter at best because Google no longer supports motif.

13

OK, So I have spent a lot of time troubleshooting this. What is everyone using now to host their phone numbers

14

Most of us pay for our services, Sipstation are a US provider, for around $28 a month now, you can get unlimited Domestic calling and one DID (Phone number), they can port over the number also. Sipstation have a module that runs directly with FreePBX and by using Sipstaion, you are putting a little back into the project. www.sipstation.com

For international calls, I personally use Flowroute, calls are per minute and are pretty cheap. There is lots of different providers out there, some better than others. I have not really had much issue with either of the above mentioned.

As mentioned, Google dropped motif a while back, but even when it was working it was not very stable. Google loved to tweak stuff and messed it up on a regular basis. It would probably be fair to say Good Riddance to it. It was more of a pain in the ass than anything I have had to deal with.

15

Sipstation $24.99 + $1.00 per did + FEDERAL UNIVERSAL SERVICE FUND $2.13 + Federal Regulatory Assessment Fee $0.17 = $28.29