2013-07-01 20:37:32.446979 [INFO] mod_dialplan_xml.c:558 Processing Barbara Ladner <barbara>->4164790606 in context
alcan.mydomain.ca
Dialplan: sofia/sipinterface_1/
barbara@alcan.mydomain.ca Regex (PASS) [outbound_dialplan.] destination_number(4164790606) =~ /^(4164790606)$/ break=on-false
2013-07-01 20:37:32.457029 [DEBUG] switch_core_state_machine.c:167 (sofia/sipinterface_1/
barbara@alcan.mydomain.ca) State Change CS_ROUTING -> CS_EXECUTE
2013-07-01 20:37:32.457029 [DEBUG] switch_core_session.c:1341 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.457029 [DEBUG] switch_core_state_machine.c:471 (sofia/sipinterface_1/
barbara@alcan.mydomain.ca) State ROUTING going to sleep
2013-07-01 20:37:32.457029 [DEBUG] switch_core_state_machine.c:416 (sofia/sipinterface_1/
barbara@alcan.mydomain.ca) Running State Change CS_EXECUTE
2013-07-01 20:37:32.457029 [DEBUG] switch_core_state_machine.c:478 (sofia/sipinterface_1/
barbara@alcan.mydomain.ca) State EXECUTE
2013-07-01 20:37:32.457029 [DEBUG] switch_core_state_machine.c:209 sofia/sipinterface_1/
barbara@alcan.mydomain.ca Standard EXECUTE
2013-07-01 20:37:32.468008 [INFO] switch_cpp.cpp:651 Sending early media
2013-07-01 20:37:32.468008 [DEBUG] switch_core_media.c:3982 AUDIO RTP [sofia/sipinterface_1/
barbara@alcan.mydomain.ca] A.B.C.D port 24402 -> 192.168.240.105 port 3000 codec: 0 ms: 20
2013-07-01 20:37:32.468008 [DEBUG] switch_rtp.c:2767 Starting timer [soft] 160 bytes per 20ms
2013-07-01 20:37:32.468008 [DEBUG] switch_core_media.c:4313 Set 2833 dtmf send payload to 101
2013-07-01 20:37:32.468008 [DEBUG] switch_core_media.c:4319 Set 2833 dtmf receive payload to 101
2013-07-01 20:37:32.468008 [DEBUG] mod_sofia.c:2105 Ring SDP:
v=0
o=FreeSWITCH 1372701050 1372701051 IN IP4 A.B.C.D
s=FreeSWITCH
c=IN IP4 A.B.C.D
t=0 0
m=audio 24402 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2013-07-01 20:37:32.468008 [DEBUG] switch_channel.c:3316 (sofia/sipinterface_1/
barbara@alcan.mydomain.ca) Callstate Change RINGING -> EARLY
2013-07-01 20:37:32.468008 [DEBUG] switch_core_session.c:861 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.468008 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.476978 [DEBUG] sofia.c:5764 Channel sofia/sipinterface_1/
barbara@alcan.mydomain.ca entering state [early][183]
v=0
o=FreeSWITCH 1372701050 1372701052 IN IP4 A.B.C.D
s=FreeSWITCH
c=IN IP4 A.B.C.D
t=0 0
m=audio 24402 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2013-07-01 20:37:32.476978 [DEBUG] switch_core_session.c:861 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.476978 [NOTICE] switch_cpp.cpp:633 Channel [sofia/sipinterface_1/
barbara@alcan.mydomain.ca] has been answered
2013-07-01 20:37:32.476978 [DEBUG] switch_channel.c:3595 (sofia/sipinterface_1/
barbara@alcan.mydomain.ca) Callstate Change EARLY -> ACTIVE
2013-07-01 20:37:32.476978 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] domain_name:
alcan.mydomain.ca2013-07-01 20:37:32.476978 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] context:
alcan.mydomain.ca
2013-07-01 20:37:32.476978 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] destination number: 4164790606
2013-07-01 20:37:32.476978 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.476978 [DEBUG] freeswitch_lua.cpp:352 DBH handle 0x7fdcb8197170 Connected.
2013-07-01 20:37:32.476978 [DEBUG] sofia.c:5764 Channel sofia/sipinterface_1/
barbara@alcan.mydomain.ca entering state [completed][200]
2013-07-01 20:37:32.476978 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) (REMOTE ONLY) [domain_name]=[
alcan.mydomain.ca]
2013-07-01 20:37:32.476978 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) (REMOTE ONLY) [sip_from_uri]=[
barbara@alcan.mydomain.ca]
EXECUTE sofia/sipinterface_1/
barbara@alcan.mydomain.ca export(nolocal:execute_on_answer=lua /usr/local/hostedsip/luascripts/call_recording.lua)
2013-07-01 20:37:32.476978 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) (REMOTE ONLY) [execute_on_answer]=[lua /usr/local/hostedsip/luascripts/call_recording.lua]
2013-07-01 20:37:32.476978 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] begin bridge the destianation number
2013-07-01 20:37:32.476978 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] user_query: select pstn_callerid,caller_id_name,caller_id_number,block_caller_id_status from user where sip_address='
barbara@alcan.mydomain.ca'
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] outbound call originate from a USER
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] pstn_callerid: USE_PHONE_SETTINGS
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] caller_id_name:
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] caller_id_number:
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] block_caller_id_status: false
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] local_stream_conf_id1
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] hold_music: local_stream://default
2013-07-01 20:37:32.486975 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [hold_music]=[local_stream://default]
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] customer_query : select caller_id_name,caller_id_number from customer where domain='
alcan.mydomain.ca'
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] caller_id_name: Alcan Cable
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] caller_id_number: 9052066900
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] outbound_caller_id_name & outbound_caller_id_number
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] outbound_caller_id_name: Alcan Cable
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [outbound_dialplan] outbound_caller_id_number: 9052066900
2013-07-01 20:37:32.486975 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [effective_caller_id_name]=[Alcan Cable]
2013-07-01 20:37:32.486975 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [effective_caller_id_number]=[9052066900]
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] domain_name:
alcan.mydomain.ca
2013-07-01 20:37:32.486975 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] context:
alcan.mydomain.ca
2013-07-01 20:37:32.486975 [INFO] switch_limit.c:126 incr called: alcan.mydomain.ca_call_count max:5, interval:0
2013-07-01 20:37:32.486975 [INFO] mod_db.c:193 Usage for alcan.mydomain.ca_call_count is now 1/5
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] destination_number: 141
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] gateway_1: utel
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] gateway_2: voipms
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] gateway_3: flowroute
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] destination_number: 14164790606
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] progress_timeout: 10
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] gateway1: utel
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] gateway2: voipms
2013-07-01 20:37:32.536989 [INFO] switch_cpp.cpp:1287 [gateway_routing.lua] gateway3: flowroute
2013-07-01 20:37:32.536989 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [hangup_after_bridge]=[true]
2013-07-01 20:37:32.536989 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [continue_on_fail]=[true]
2013-07-01 20:37:32.536989 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [pstn_direction]=[PSTN_OUTBOUND]
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) [pstn_direction]=[PSTN_OUTBOUND]
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) (REMOTE ONLY) [route_destination_number]=[14164790606]
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1222 EXPORT (export_vars) (REMOTE ONLY) [route_prefix]=[1416]
2013-07-01 20:37:32.536989 [DEBUG] mod_dptools.c:1373 sofia/sipinterface_1/
barbara@alcan.mydomain.ca SET [progress_timeout]=[10]
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1222 EXPORT (bridge_export_vars) (REMOTE ONLY) [gateway]=[utel]
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1176 sofia/sipinterface_1/
barbara@alcan.mydomain.ca EXPORTING[export_vars] [execute_on_answer]=[lua /usr/local/hostedsip/luascripts/call_recording.lua] to event
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1176 sofia/sipinterface_1/
barbara@alcan.mydomain.ca EXPORTING[export_vars] [pstn_direction]=[PSTN_OUTBOUND] to event
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1176 sofia/sipinterface_1/
barbara@alcan.mydomain.ca EXPORTING[export_vars] [route_destination_number]=[14164790606] to event
2013-07-01 20:37:32.536989 [DEBUG] switch_channel.c:1176 sofia/sipinterface_1/
barbara@alcan.mydomain.ca EXPORTING[export_vars] [route_prefix]=[1416] to event
2013-07-01 20:37:32.536989 [DEBUG] switch_ivr_originate.c:2050 Parsing global variables
2013-07-01 20:37:32.536989 [DEBUG] switch_event.c:1617 Parsing variable [sip_cid_type]=[none]
2013-07-01 20:37:32.536989 [NOTICE] switch_channel.c:1030 New Channel sofia/sipinterface_2/14164790606 [9584d698-e2af-11e2-bd35-8118757a60c5]
2013-07-01 20:37:32.536989 [DEBUG] mod_sofia.c:4420 (sofia/sipinterface_2/14164790606) State Change CS_NEW -> CS_INIT
2013-07-01 20:37:32.536989 [DEBUG] switch_core_session.c:1341 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:416 (sofia/sipinterface_2/14164790606) Running State Change CS_INIT
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:455 (sofia/sipinterface_2/14164790606) State INIT
2013-07-01 20:37:32.536989 [DEBUG] mod_sofia.c:87 sofia/sipinterface_2/14164790606 SOFIA INIT
2013-07-01 20:37:32.536989 [DEBUG] sofia_glue.c:1220 Local SDP:
v=0
o=FreeSWITCH 1372703258 1372703259 IN IP4 A.B.C.D
s=FreeSWITCH
c=IN IP4 A.B.C.D
t=0 0
m=audio 22194 RTP/AVP 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2013-07-01 20:37:32.536989 [DEBUG] mod_sofia.c:114 (sofia/sipinterface_2/14164790606) State Change CS_INIT -> CS_ROUTING
2013-07-01 20:37:32.536989 [DEBUG] switch_core_session.c:1341 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:455 (sofia/sipinterface_2/14164790606) State INIT going to sleep
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:416 (sofia/sipinterface_2/14164790606) Running State Change CS_ROUTING
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:471 (sofia/sipinterface_2/14164790606) State ROUTING
2013-07-01 20:37:32.536989 [DEBUG] mod_sofia.c:137 sofia/sipinterface_2/14164790606 SOFIA ROUTING
2013-07-01 20:37:32.536989 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_2/14164790606) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-07-01 20:37:32.536989 [DEBUG] switch_core_session.c:1341 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:471 (sofia/sipinterface_2/14164790606) State ROUTING going to sleep
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:416 (sofia/sipinterface_2/14164790606) Running State Change CS_CONSUME_MEDIA
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:490 (sofia/sipinterface_2/14164790606) State CONSUME_MEDIA
2013-07-01 20:37:32.536989 [DEBUG] switch_core_state_machine.c:490 (sofia/sipinterface_2/14164790606) State CONSUME_MEDIA going to sleep
2013-07-01 20:37:32.536989 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:32.536989 [DEBUG] sofia.c:5764 Channel sofia/sipinterface_2/14164790606 entering state [calling][0]
2013-07-01 20:37:32.566973 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:32.566973 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:32.566973 [DEBUG] sofia.c:5764 Channel sofia/sipinterface_2/14164790606 entering state [calling][0]
2013-07-01 20:37:32.846981 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.857157 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.857157 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_1/
barbara@alcan.mydomain.ca [BREAK]
2013-07-01 20:37:32.857157 [DEBUG] sofia.c:5764 Channel sofia/sipinterface_1/
barbara@alcan.mydomain.ca entering state [ready][200]
2013-07-01 20:37:39.266976 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:39.266976 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:39.266976 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:39.266976 [DEBUG] switch_core_session.c:1006 Send signal sofia/sipinterface_2/14164790606 [BREAK]
2013-07-01 20:37:39.266976 [DEBUG] sofia.c:5764 Channel sofia/sipinterface_2/14164790606 entering state [proceeding][180]
2013-07-01 20:37:39.266976 [NOTICE] sofia.c:5854 Ring-Ready sofia/sipinterface_2/14164790606!
2013-07-01 20:37:39.266976 [DEBUG] switch_channel.c:3180 (sofia/sipinterface_2/14164790606) Callstate Change DOWN -> RINGING