[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:2740 do_setnat: Setting NAT on RTP to Off
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:2750 do_setnat: Setting NAT on UDPTL to Off
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:4508 sip_alloc: Allocating new SIP dialog for 6d458cfd8e0750b5@RTIzNQ.. - INVITE (With RTP)
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jun 12 20:21:01] DEBUG[19683]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:01] DEBUG[19683]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'E235.XXXXXXX.com:5060'
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:2740 do_setnat: Setting NAT on RTP to Off
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:2750 do_setnat: Setting NAT on UDPTL to Off
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel <none>
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:13854 handle_request_invite: Checking SIP call limits for device 
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:3992 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:3993 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:3994 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:3995 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:4018 sip_new: This channel will not be able to handle video.
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:8236 build_route: build_route: Contact hop: <sip:CALLING_IP:5060;logitel=LOGIT-oo1nbt455iov3;transport=udp>
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:13933 handle_request_invite: SIP/5060-008e9c30: New call is still down.... Trying... 
[Jun 12 20:21:01] DEBUG[19683]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-008e9c30
[Jun 12 20:21:01] DEBUG[19683]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Jun 12 20:21:01] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-008e9c30
[Jun 12 20:21:01] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060-008e9c30
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-008e9c30' AND host = 'dynamic'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13604442222'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-008e9c30'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1000.00000,99,0,2000,t,0,f'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:197 array: array (credit|tariff|term_inuse|max_out_channels|fallback|nbused|prepaid_termination=1000.00000,99,0,2000,t,0,f)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (credit=1000.00000)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tariff=99)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (term_inuse=0)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (max_out_channels=2000)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (fallback=t)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (nbused=0)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (prepaid_termination=f)
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '10'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'FALSE'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13604442222'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551313'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '11'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '11'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1360'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'WA'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1360'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'WA'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SYS USE INTRA,0,101,263,INTRASTATE  CARRIER,newburypt,23481303,13602701,0.00434,6,6,0.005208,6,6,358,+,SIP,CARRIER_IP,,358,+,SIP,CARRIER_IP,,,397,397,,'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:197 array: array (tariffgroupname|lcrtype|idtariffgroup|idtariffplan|tariffname|destination|id|dialprefix|buyrate|buyrateinitblock|buyrateincrement|rateinitial|initblock|billingblock|tp_id_trunk|tp_trunkprefix|tp_providertech|tp_providerip|tp_removeprefix|tp_id_trunk|tp_trunkprefix|tp_providertech|tp_providerip|tp_removeprefix|musiconhold|tp_failover_trunk|rt_failover_trunk|tp_addparameter_trunk|rt_addparameter_trunk=SYS USE INTRA,0,101,263,INTRASTATE  CARRIER,newburypt,23481303,13602701,0.00434,6,6,0.005208,6,6,358,+,SIP,CARRIER_IP,,358,+,SIP,CARRIER_IP,,,397,397,,)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tariffgroupname=SYS USE INTRA)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (lcrtype=0)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (idtariffgroup=101)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (idtariffplan=263)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tariffname=INTRASTATE  CARRIER)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (destination=newburypt)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (id=23481303)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (dialprefix=13602701)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (buyrate=0.00434)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (buyrateinitblock=6)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (buyrateincrement=6)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (rateinitial=0.005208)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (initblock=6)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (billingblock=6)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_id_trunk=358)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_trunkprefix=+)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_providertech=SIP)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_providerip=CARRIER_IP)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_removeprefix=)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_id_trunk=358)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_trunkprefix=+)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_providertech=SIP)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_providerip=CARRIER_IP)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_removeprefix=)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (musiconhold=)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_failover_trunk=397)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (rt_failover_trunk=397)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (tp_addparameter_trunk=)
[Jun 12 20:21:01] DEBUG[19692]: func_strings.c:210 array: array set value (rt_addparameter_trunk=(null))
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '192012.288786'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '11520737'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:01] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Dial'
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:15874 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:4508 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:2786 create_addr_from_peer: Our T38 capability (3856)
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:2740 do_setnat: Setting NAT on RTP to Off
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:2750 do_setnat: Setting NAT on UDPTL to Off
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3992 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3993 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3994 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3995 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3997 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:4018 sip_new: This channel will not be able to handle video.
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:17520 sip_set_rtp_peer: Early remote bridge setting SIP '7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER' - Sending media to CALLING_IP
[Jun 12 20:21:01] DEBUG[19692]: rtp.c:1632 ast_rtp_make_compatible: Seeded SDP of 'SIP/CARRIER_IP-008fd9e0' with that of 'SIP/5060-008e9c30'
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable ext.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable timeout.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rt_addparameter_trunk.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_addparameter_trunk.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rt_failover_trunk.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_failover_trunk.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable musiconhold.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_removeprefix.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_providerip.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_providertech.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_trunkprefix.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_id_trunk.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable billingblock.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable initblock.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rateinitial.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable buyrateincrement.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable buyrateinitblock.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable buyrate.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable dialprefix.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable id.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable destination.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tariffname.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable idtariffplan.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable idtariffgroup.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable lcrtype.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tariffgroupname.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable i.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rows.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable handle.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tariff.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable intrastate.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable dststate.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable srcstate.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable dst.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable src.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tmp.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable writecdr.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable prepaid_termination.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable nbused.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable fallback.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable max_out_channels.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable term_inuse.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable credit.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable id_did.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable sipiax.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable username.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable FROM_IP.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPDOmaIN.
[Jun 12 20:21:01] DEBUG[19692]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:2998 sip_call: Outgoing Call for +13604442222
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:3013 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:01] DEBUG[19692]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:2215 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER' Request 102: Found
[Jun 12 20:21:01] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 100 to standard invite
[Jun 12 20:21:01] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060-008e9c30 - state 4 (Invalid)
[Jun 12 20:21:01] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Jun 12 20:21:01] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060' AND host = 'dynamic'
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:01] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060'
[Jun 12 20:21:01] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:4508 sip_alloc: Allocating new SIP dialog for 160d9d3f313da31553a042070140397c@66.240.234.81 - OPTIONS (No RTP)
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:2215 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER' Request 102: Found
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 183 to standard invite
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel SIP/CARRIER_IP-008fd9e0
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:03] DEBUG[19683]: chan_sip.c:5477 process_sdp: We have an owner, now see if we need to change this call
[Jun 12 20:21:03] DEBUG[19692]: chan_sip.c:17520 sip_set_rtp_peer: Early remote bridge setting SIP '6d458cfd8e0750b5@RTIzNQ..' - Sending media to CARRIER_IP
[Jun 12 20:21:03] DEBUG[19692]: rtp.c:1561 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/5060-008e9c30' with that of 'SIP/CARRIER_IP-008fd9e0'
[Jun 12 20:21:03] DEBUG[19692]: chan_sip.c:6659 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 12 20:21:03] DEBUG[19692]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:03] DEBUG[19692]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:03] DEBUG[19692]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:03] DEBUG[19692]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:2157 __sip_ack: Acked pending invite 102
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER' of Request 102: match Not Found
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 200 to standard invite
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel SIP/CARRIER_IP-008fd9e0
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:5477 process_sdp: We have an owner, now see if we need to change this call
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jun 12 20:21:08] DEBUG[19683]: chan_sip.c:8236 build_route: build_route: Contact hop: <sip:+13604442222@4.55.21.97:5060>
[Jun 12 20:21:08] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP-008fd9e0
[Jun 12 20:21:08] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP
[Jun 12 20:21:08] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP-008fd9e0
[Jun 12 20:21:08] DEBUG[19692]: rtp.c:1561 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/5060-008e9c30' with that of 'SIP/CARRIER_IP-008fd9e0'
[Jun 12 20:21:08] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP-008fd9e0
[Jun 12 20:21:08] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-008e9c30
[Jun 12 20:21:08] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Jun 12 20:21:08] DEBUG[19692]: chan_sip.c:3646 sip_answer: SIP answering channel: SIP/5060-008e9c30
[Jun 12 20:21:08] DEBUG[19692]: chan_sip.c:6659 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 12 20:21:08] DEBUG[19692]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:08] DEBUG[19692]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:08] DEBUG[19692]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:08] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:08] DEBUG[19692]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:08] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-008fd9e0' AND host = 'dynamic'
[Jun 12 20:21:08] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:08] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-008fd9e0'
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP-008fd9e0 - state 4 (Invalid)
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP
[Jun 12 20:21:09] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP - state 1 (Not in use)
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-008e9c30
[Jun 12 20:21:09] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060-008e9c30
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-008e9c30' AND host = 'dynamic'
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-008e9c30'
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060-008e9c30 - state 4 (Invalid)
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Jun 12 20:21:09] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060' AND host = 'dynamic'
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:09] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060'
[Jun 12 20:21:09] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Jun 12 20:21:09] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jun 12 20:21:09] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '6d458cfd8e0750b5@RTIzNQ..' of Response 5: match Not Found
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:2740 do_setnat: Setting NAT on RTP to Off
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:2750 do_setnat: Setting NAT on UDPTL to Off
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:4508 sip_alloc: Allocating new SIP dialog for b4ea76c27c2269e4@RTIzNQ.. - INVITE (With RTP)
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jun 12 20:21:13] DEBUG[19683]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:13] DEBUG[19683]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'E235.XXXXXXX.com:5060'
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:2740 do_setnat: Setting NAT on RTP to Off
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:2750 do_setnat: Setting NAT on UDPTL to Off
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel <none>
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:13854 handle_request_invite: Checking SIP call limits for device 
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:3992 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:3993 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:3994 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:3995 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:4018 sip_new: This channel will not be able to handle video.
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:8236 build_route: build_route: Contact hop: <sip:CALLING_IP:5060;logitel=LOGIT-oo1nbt455iov3;transport=udp>
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:13933 handle_request_invite: SIP/5060-009127d0: New call is still down.... Trying... 
[Jun 12 20:21:13] DEBUG[19683]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-009127d0
[Jun 12 20:21:13] DEBUG[19683]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Jun 12 20:21:13] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-009127d0
[Jun 12 20:21:13] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060-009127d0
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-009127d0' AND host = 'dynamic'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1000.00000,99,1,2000,t,0,f'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:197 array: array (credit|tariff|term_inuse|max_out_channels|fallback|nbused|prepaid_termination=1000.00000,99,1,2000,t,0,f)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (credit=1000.00000)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tariff=99)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (term_inuse=1)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (max_out_channels=2000)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (fallback=t)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (nbused=0)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (prepaid_termination=f)
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '10'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'FALSE'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-009127d0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551313'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '11'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '11'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1360'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'WA'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1360'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'WA'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SYS USE INTRA,0,101,263,INTRASTATE  CARRIER,beverly,23481685,13602992,0.00781,6,6,0.009372,6,6,358,+,SIP,CARRIER_IP,,358,+,SIP,CARRIER_IP,,,397,397,,'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:197 array: array (tariffgroupname|lcrtype|idtariffgroup|idtariffplan|tariffname|destination|id|dialprefix|buyrate|buyrateinitblock|buyrateincrement|rateinitial|initblock|billingblock|tp_id_trunk|tp_trunkprefix|tp_providertech|tp_providerip|tp_removeprefix|tp_id_trunk|tp_trunkprefix|tp_providertech|tp_providerip|tp_removeprefix|musiconhold|tp_failover_trunk|rt_failover_trunk|tp_addparameter_trunk|rt_addparameter_trunk=SYS USE INTRA,0,101,263,INTRASTATE  CARRIER,beverly,23481685,13602992,0.00781,6,6,0.009372,6,6,358,+,SIP,CARRIER_IP,,358,+,SIP,CARRIER_IP,,,397,397,,)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tariffgroupname=SYS USE INTRA)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (lcrtype=0)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (idtariffgroup=101)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (idtariffplan=263)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tariffname=INTRASTATE  CARRIER)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (destination=beverly)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (id=23481685)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (dialprefix=13602992)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (buyrate=0.00781)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (buyrateinitblock=6)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (buyrateincrement=6)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (rateinitial=0.009372)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (initblock=6)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (billingblock=6)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_id_trunk=358)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_trunkprefix=+)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_providertech=SIP)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_providerip=CARRIER_IP)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_removeprefix=)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_id_trunk=358)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_trunkprefix=+)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_providertech=SIP)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_providerip=CARRIER_IP)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_removeprefix=)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (musiconhold=)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_failover_trunk=397)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (rt_failover_trunk=397)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (tp_addparameter_trunk=)
[Jun 12 20:21:13] DEBUG[19694]: func_strings.c:210 array: array set value (rt_addparameter_trunk=(null))
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '106700.810926'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '6402048'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:13] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Dial'
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:15874 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:4508 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:2786 create_addr_from_peer: Our T38 capability (3856)
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:2740 do_setnat: Setting NAT on RTP to Off
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:2750 do_setnat: Setting NAT on UDPTL to Off
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3992 sip_new: *** Our native formats are 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3993 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3994 sip_new: *** Our capabilities are 0x104 (ulaw|g729) 
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3995 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3997 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:4018 sip_new: This channel will not be able to handle video.
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:17520 sip_set_rtp_peer: Early remote bridge setting SIP '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' - Sending media to CALLING_IP
[Jun 12 20:21:13] DEBUG[19694]: rtp.c:1632 ast_rtp_make_compatible: Seeded SDP of 'SIP/CARRIER_IP-00925b30' with that of 'SIP/5060-009127d0'
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable ext.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable timeout.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rt_addparameter_trunk.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_addparameter_trunk.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rt_failover_trunk.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_failover_trunk.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable musiconhold.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_removeprefix.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_providerip.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_providertech.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_trunkprefix.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tp_id_trunk.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable billingblock.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable initblock.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rateinitial.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable buyrateincrement.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable buyrateinitblock.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable buyrate.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable dialprefix.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable id.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable destination.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tariffname.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable idtariffplan.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable idtariffgroup.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable lcrtype.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tariffgroupname.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable i.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable rows.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable handle.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tariff.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable intrastate.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable dststate.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable srcstate.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable dst.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable src.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable tmp.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable writecdr.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable prepaid_termination.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable nbused.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable fallback.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable max_out_channels.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable term_inuse.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable credit.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable id_did.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable sipiax.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable username.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable FROM_IP.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPDOmaIN.
[Jun 12 20:21:13] DEBUG[19694]: channel.c:3277 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:2998 sip_call: Outgoing Call for +13605551212
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:3013 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:13] DEBUG[19694]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:2215 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' Request 102: Found
[Jun 12 20:21:13] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 100 to standard invite
[Jun 12 20:21:13] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060-009127d0 - state 4 (Invalid)
[Jun 12 20:21:13] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Jun 12 20:21:13] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060' AND host = 'dynamic'
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:13] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060'
[Jun 12 20:21:13] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Jun 12 20:21:14] DEBUG[19683]: chan_sip.c:2215 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' Request 102: Found
[Jun 12 20:21:14] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 180 to standard invite
[Jun 12 20:21:14] DEBUG[19683]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP-00925b30
[Jun 12 20:21:14] DEBUG[19683]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP
[Jun 12 20:21:14] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel SIP/CARRIER_IP-00925b30
[Jun 12 20:21:14] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:14] DEBUG[19683]: chan_sip.c:5477 process_sdp: We have an owner, now see if we need to change this call
[Jun 12 20:21:14] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP-00925b30
[Jun 12 20:21:14] DEBUG[19694]: chan_sip.c:17520 sip_set_rtp_peer: Early remote bridge setting SIP 'b4ea76c27c2269e4@RTIzNQ..' - Sending media to CARRIER_IP
[Jun 12 20:21:14] DEBUG[19694]: rtp.c:1561 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/5060-009127d0' with that of 'SIP/CARRIER_IP-00925b30'
[Jun 12 20:21:14] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP-00925b30
[Jun 12 20:21:14] DEBUG[19694]: rtp.c:1561 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/5060-009127d0' with that of 'SIP/CARRIER_IP-00925b30'
[Jun 12 20:21:14] DEBUG[19694]: chan_sip.c:6659 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 12 20:21:14] DEBUG[19694]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:14] DEBUG[19694]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:14] DEBUG[19694]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:14] DEBUG[19694]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:14] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:14] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-00925b30' AND host = 'dynamic'
[Jun 12 20:21:14] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:14] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-00925b30'
[Jun 12 20:21:14] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP-00925b30 - state 4 (Invalid)
[Jun 12 20:21:14] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP
[Jun 12 20:21:14] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP
[Jun 12 20:21:14] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP - state 1 (Not in use)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:2157 __sip_ack: Acked pending invite 102
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' of Request 102: match Not Found
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 200 to standard invite
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel SIP/CARRIER_IP-00925b30
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5477 process_sdp: We have an owner, now see if we need to change this call
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:8236 build_route: build_route: Contact hop: <sip:+13605551212@4.55.21.97:5060>
[Jun 12 20:21:17] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP-00925b30
[Jun 12 20:21:17] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP-00925b30
[Jun 12 20:21:17] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP-00925b30
[Jun 12 20:21:17] DEBUG[19694]: rtp.c:1561 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/5060-009127d0' with that of 'SIP/CARRIER_IP-00925b30'
[Jun 12 20:21:17] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-009127d0
[Jun 12 20:21:17] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Jun 12 20:21:17] DEBUG[19694]: chan_sip.c:3646 sip_answer: SIP answering channel: SIP/5060-009127d0
[Jun 12 20:21:17] DEBUG[19694]: chan_sip.c:6659 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 12 20:21:17] DEBUG[19694]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:17] DEBUG[19694]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-00925b30' AND host = 'dynamic'
[Jun 12 20:21:17] DEBUG[19694]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:17] DEBUG[19694]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-00925b30'
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP-00925b30 - state 4 (Invalid)
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP
[Jun 12 20:21:17] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP - state 1 (Not in use)
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-009127d0
[Jun 12 20:21:17] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060-009127d0
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-009127d0' AND host = 'dynamic'
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-009127d0'
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060-009127d0 - state 4 (Invalid)
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Jun 12 20:21:17] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060' AND host = 'dynamic'
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:17] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060'
[Jun 12 20:21:17] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on 'b4ea76c27c2269e4@RTIzNQ..' of Response 6: match Not Found
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel SIP/5060-008e9c30
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5477 process_sdp: We have an owner, now see if we need to change this call
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:14007 handle_request_invite: SIP/5060-008e9c30: This call is UP.... 
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6659 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel SIP/5060-009127d0
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:5477 process_sdp: We have an owner, now see if we need to change this call
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:14007 handle_request_invite: SIP/5060-009127d0: This call is UP.... 
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6659 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '6d458cfd8e0750b5@RTIzNQ..' of Response 6: match Found
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received ACK (6) - Command in SIP ACK
[Jun 12 20:21:17] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on 'b4ea76c27c2269e4@RTIzNQ..' of Response 7: match Found
[Jun 12 20:21:21] DEBUG[19683]: chan_sip.c:4508 sip_alloc: Allocating new SIP dialog for 78aab1ed136a81674158e02a0ef811fe@64.34.174.144 - OPTIONS (No RTP)
[Jun 12 20:21:21] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received BYE (8) - Command in SIP BYE
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:1655 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:14726 handle_request_bye: Received bye, issuing owner hangup
[Jun 12 20:21:33] DEBUG[19692]: rtp.c:2945 bridge_native_loop: Oooh, got a hangup
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:17523 sip_set_rtp_peer: Sending reinvite on SIP '6d458cfd8e0750b5@RTIzNQ..' - It's audio soon redirected to IP ASTERISK_SERVER
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:1643 initialize_initreq: Initializing already initialized SIP dialog 6d458cfd8e0750b5@RTIzNQ.. (presumably reinvite)
[Jun 12 20:21:33] DEBUG[19692]: channel.c:4008 ast_channel_bridge: Returning from native bridge, channels: SIP/5060-008e9c30, SIP/CARRIER_IP-008fd9e0
[Jun 12 20:21:33] DEBUG[19692]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/CARRIER_IP-008fd9e0'
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:3485 sip_hangup: Hangup call SIP/CARRIER_IP-008fd9e0, SIP callid 7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER)
[Jun 12 20:21:33] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP-008fd9e0
[Jun 12 20:21:33] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP
[Jun 12 20:21:33] DEBUG[19692]: rtp.c:1510 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP-008fd9e0
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP-008fd9e0
[Jun 12 20:21:33] DEBUG[19692]: app_dial.c:1741 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:2427 __ast_pbx_run: Spawn extension (wc-billing-main,13604442222,128) exited non-zero on 'SIP/5060-008e9c30'
[Jun 12 20:21:33] DEBUG[19692]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/5060-008e9c30'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-008fd9e0' AND host = 'dynamic'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'ODBCFinish'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '24'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-008fd9e0'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '4'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '30'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.156240'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.002604'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '24'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '4'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '30'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.130200'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.002170'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP-008fd9e0 - state 4 (Invalid)
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP - state 1 (Not in use)
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13604442222'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SEATTLE  -  WA'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: func_strings.c:197 array: array (dst=SEATTLE  -  WA)
[Jun 12 20:21:33] DEBUG[19692]: func_strings.c:210 array: array set value (dst=SEATTLE  -  WA)
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '18'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '18'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SEATTLE  -  WA'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:33] DEBUG[19692]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19692]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/5060-008e9c30'
[Jun 12 20:21:33] DEBUG[19692]: chan_sip.c:3485 sip_hangup: Hangup call SIP/5060-008e9c30, SIP callid 6d458cfd8e0750b5@RTIzNQ..)
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-008e9c30
[Jun 12 20:21:33] DEBUG[19692]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-008e9c30
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060-008e9c30
[Jun 12 20:21:33] DEBUG[19692]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: inserting a CDR record.
[Jun 12 20:21:33] DEBUG[19692]: cdr_addon_mysql.c:245 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2009-06-12 20:21:01','\"13605551313\" <13605551212>','13605551212','h','wc-billing-main', 'SIP/5060-008e9c30','SIP/CARRIER_IP-008fd9e0','Dial','SIP/CARRIER_IP/+13604442222|300',32,25,'ANSWERED',3,'XXX000000')
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-008e9c30' AND host = 'dynamic'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-008e9c30'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060-008e9c30 - state 4 (Invalid)
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060' AND host = 'dynamic'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2215 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6d458cfd8e0750b5@RTIzNQ..' Request 102: Found
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 100 to standard invite
Really destroying SIP dialog '7b4f419b6eab5aa17cff191567bb1b77@ASTERISK_SERVER' Method: BYE
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2157 __sip_ack: Acked pending invite 102
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '6d458cfd8e0750b5@RTIzNQ..' of Request 102: match Not Found
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 200 to standard invite
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel <none>
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:8236 build_route: build_route: Contact hop: <sip:CALLING_IP:5060;logitel=LOGIT-oo1nbt455iov3;transport=udp>
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '6d458cfd8e0750b5@RTIzNQ..' of Request 103: match Not Found
Really destroying SIP dialog '6d458cfd8e0750b5@RTIzNQ..' Method: ACK
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:15174 handle_request: **** Received BYE (8) - Command in SIP BYE
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:1655 sip_alreadygone: Setting SIP_ALREADYGONE on dialog b4ea76c27c2269e4@RTIzNQ..
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:14726 handle_request_bye: Received bye, issuing owner hangup
[Jun 12 20:21:33] DEBUG[19694]: rtp.c:2945 bridge_native_loop: Oooh, got a hangup
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:17523 sip_set_rtp_peer: Sending reinvite on SIP '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' - It's audio soon redirected to IP ASTERISK_SERVER
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:6423 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:6424 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:6555 add_sdp: -- Done with adding codecs to SDP
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:6600 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:1643 initialize_initreq: Initializing already initialized SIP dialog 79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER (presumably reinvite)
[Jun 12 20:21:33] DEBUG[19694]: channel.c:4008 ast_channel_bridge: Returning from native bridge, channels: SIP/5060-009127d0, SIP/CARRIER_IP-00925b30
[Jun 12 20:21:33] DEBUG[19694]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/CARRIER_IP-00925b30'
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:3485 sip_hangup: Hangup call SIP/CARRIER_IP-00925b30, SIP callid 79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER)
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Jun 12 20:21:33] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP-00925b30
[Jun 12 20:21:33] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/CARRIER_IP
[Jun 12 20:21:33] DEBUG[19694]: rtp.c:1510 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Jun 12 20:21:33] DEBUG[19694]: app_dial.c:1741 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:2427 __ast_pbx_run: Spawn extension (wc-billing-main,13605551212,128) exited non-zero on 'SIP/5060-009127d0'
[Jun 12 20:21:33] DEBUG[19694]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/5060-009127d0'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP-00925b30
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP-00925b30
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'ODBCFinish'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-00925b30' AND host = 'dynamic'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '1'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '15'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '18'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = 'CARRIER_IP-00925b30'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.168696'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.002812'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '15'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '18'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.140580'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0.002343'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '0'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP-00925b30 - state 4 (Invalid)
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - CARRIER_IP
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer CARRIER_IP
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/CARRIER_IP - state 1 (Not in use)
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Goto'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '13605551212'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SEATTLE  -  WA'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: func_strings.c:197 array: array (dst=SEATTLE  -  WA)
[Jun 12 20:21:33] DEBUG[19694]: func_strings.c:210 array: array set value (dst=SEATTLE  -  WA)
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '14'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1748 pbx_substitute_variables_helper_full: Expression result is '14'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'GotoIf'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SEATTLE  -  WA'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is ''
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'Set'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'XXX000000'
[Jun 12 20:21:33] DEBUG[19694]: pbx.c:1831 pbx_extension_helper: Launching 'NoOp'
[Jun 12 20:21:33] DEBUG[19694]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/5060-009127d0'
[Jun 12 20:21:33] DEBUG[19694]: chan_sip.c:3485 sip_hangup: Hangup call SIP/5060-009127d0, SIP callid b4ea76c27c2269e4@RTIzNQ..)
[Jun 12 20:21:33] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-009127d0
[Jun 12 20:21:33] DEBUG[19694]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-009127d0
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060-009127d0
[Jun 12 20:21:33] DEBUG[19694]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: inserting a CDR record.
[Jun 12 20:21:33] DEBUG[19694]: cdr_addon_mysql.c:245 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2009-06-12 20:21:13','\"13605551313\" <13605551212>','13605551212','h','wc-billing-main', 'SIP/5060-009127d0','SIP/CARRIER_IP-00925b30','Dial','SIP/CARRIER_IP/+13605551212|300',20,16,'ANSWERED',3,'XXX000000')
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-009127d0' AND host = 'dynamic'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060-009127d0'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060-009127d0 - state 4 (Invalid)
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Jun 12 20:21:33] DEBUG[19681]: chan_sip.c:15805 sip_devicestate: Checking device state for peer 5060
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060' AND host = 'dynamic'
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:653 mysql_reconnect: MySQL RealTime: Everything is fine.
[Jun 12 20:21:33] DEBUG[19681]: res_config_mysql.c:140 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM cc_sip_buddies WHERE name = '5060'
[Jun 12 20:21:33] DEBUG[19681]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2215 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' Request 103: Found
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 100 to standard invite
Really destroying SIP dialog 'b4ea76c27c2269e4@RTIzNQ..' Method: BYE
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2157 __sip_ack: Acked pending invite 103
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' of Request 103: match Not Found
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:11989 handle_response_invite: SIP response 200 to standard invite
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:5390 process_sdp: T38 state changed to 0 on channel <none>
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:5470 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:8175 build_route: build_route: Retaining previous route: <sip:+13605551212@4.55.21.97:5060>
[Jun 12 20:21:33] DEBUG[19683]: chan_sip.c:2174 __sip_ack: Stopping retransmission on '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' of Request 104: match Not Found
Really destroying SIP dialog '79a364800f3698ff01fd54c000de034c@ASTERISK_SERVER' Method: INVITE
[Jun 12 20:21:35] DEBUG[19683]: chan_sip.c:2094 __sip_autodestruct: Auto destroying SIP dialog '160d9d3f313da31553a042070140397c@66.240.234.81'
[Jun 12 20:21:35] DEBUG[19683]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog 160d9d3f313da31553a042070140397c@66.240.234.81
Really destroying SIP dialog '160d9d3f313da31553a042070140397c@66.240.234.81' Method: OPTIONS