[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