+OK log level  [7]
2017-06-12 11:38:16.832244 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'internal' for [601@pbx.domain.com] from ip 10.1.10.150
2017-06-12 11:38:16.932252 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f21f004fbb0 Connected.
2017-06-12 11:38:16.932252 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f21f004fbb0 released.
2017-06-12 11:40:48.612287 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f21f0058170 Connected.
2017-06-12 11:40:48.612287 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f21f0058170 released.
2017-06-12 11:41:48.052298 [ERR] switch_core_sqldb.c:1197 SQL ERR: [select name, description, syntax, ikey from interfaces where hostname='pbx.domain.com' and type = 'application' and description != '' order by type,name] database disk image is malformed
2017-06-12 11:45:30.032256 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/8012790596@67.211.74.200 [d60e4737-94ed-4341-a352-ac554deff4bb]
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_NEW (Cur 1 Tot 177)
2017-06-12 11:45:30.032256 [DEBUG] sofia.c:9834 sofia/internal/8012790596@67.211.74.200 receiving invite from 67.211.74.200:5060 version: 1.6.17 -34-0fc0946 64bit
2017-06-12 11:45:30.032256 [DEBUG] sofia.c:9950 IP 67.211.74.200 Approved by acl "domains[]". Access Granted.
2017-06-12 11:45:30.032256 [DEBUG] sofia.c:7048 Channel sofia/internal/8012790596@67.211.74.200 entering state [received][100]
2017-06-12 11:45:30.032256 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 3326058550 3326058550 IN IP4 67.207.47.117
s=-
c=IN IP4 67.207.47.117
t=0 0
m=audio 35212 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:10
a=silenceSupp:off - - - -

2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:10:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:10:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4472 Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a near-match
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:10:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:10:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4543 Substituting codec PCMU@10i@8000h@1c
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/8012790596@67.211.74.200 PCMU/8000 10 ms 80 samples 64000 bits 1 channels
2017-06-12 11:45:30.032256 [DEBUG] switch_core_codec.c:111 sofia/internal/8012790596@67.211.74.200 Original read codec set to PCMU:0
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:45:30.032256 [DEBUG] switch_core_media.c:4754 sofia/internal/8012790596@67.211.74.200 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:45:30.032256 [DEBUG] sofia.c:7471 (sofia/internal/8012790596@67.211.74.200) State Change CS_NEW -> CS_INIT
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/8012790596@67.211.74.200) State NEW
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_INIT (Cur 1 Tot 177)
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/8012790596@67.211.74.200) State INIT
2017-06-12 11:45:30.032256 [DEBUG] mod_sofia.c:90 sofia/internal/8012790596@67.211.74.200 SOFIA INIT
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:40 sofia/internal/8012790596@67.211.74.200 Standard INIT
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/8012790596@67.211.74.200) State Change CS_INIT -> CS_ROUTING
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/8012790596@67.211.74.200) State INIT going to sleep
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_ROUTING (Cur 1 Tot 177)
2017-06-12 11:45:30.032256 [DEBUG] switch_channel.c:2249 (sofia/internal/8012790596@67.211.74.200) Callstate Change DOWN -> RINGING
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/8012790596@67.211.74.200) State ROUTING
2017-06-12 11:45:30.032256 [DEBUG] mod_sofia.c:143 sofia/internal/8012790596@67.211.74.200 SOFIA ROUTING
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8012790596@67.211.74.200 Standard ROUTING
2017-06-12 11:45:30.032256 [INFO] mod_dialplan_xml.c:637 Processing MICHAEL JOHNSON <8012790596>->8018545166 in context public
2017-06-12 11:45:30.032256 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:30.032256 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [public->After_Hours_Sunday] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [After_Hours_Sunday] context(public) =~ /public/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Date/TimeMatch (FAIL) [After_Hours_Sunday] break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [public->After_Hours_Saturdays] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [After_Hours_Saturdays] context(public) =~ /public/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Date/TimeMatch (FAIL) [After_Hours_Saturdays] break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [public->After_Hours_Evenings] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [After_Hours_Evenings] context(public) =~ /public/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Date/TimeMatch (FAIL) [After_Hours_Evenings] break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [public->After_Hours_Mornings] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [After_Hours_Mornings] context(public) =~ /public/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Date/TimeMatch (FAIL) [After_Hours_Mornings] break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [public->Normal_Open_Hours] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [Normal_Open_Hours] context(public) =~ /public/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [Normal_Open_Hours] destination_number(8018545166) =~ /^.*$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(call_direction=inbound) INLINE
EXECUTE sofia/internal/8012790596@67.211.74.200 set(call_direction=inbound)
2017-06-12 11:45:30.032256 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [call_direction]=[inbound]
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(domain_uuid=cb0d02b2-e91e-42c4-b233-9786ecd723a4) INLINE
EXECUTE sofia/internal/8012790596@67.211.74.200 set(domain_uuid=cb0d02b2-e91e-42c4-b233-9786ecd723a4)
2017-06-12 11:45:30.032256 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [domain_uuid]=[cb0d02b2-e91e-42c4-b233-9786ecd723a4]
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(domain_name=pbx.domain.com) INLINE
EXECUTE sofia/internal/8012790596@67.211.74.200 set(domain_name=pbx.domain.com)
2017-06-12 11:45:30.032256 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [domain_name]=[pbx.domain.com]
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(call_direction=inbound)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action transfer(5001 XML pbx.domain.com)
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/8012790596@67.211.74.200) State Change CS_ROUTING -> CS_EXECUTE
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/8012790596@67.211.74.200) State ROUTING going to sleep
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_EXECUTE (Cur 1 Tot 177)
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8012790596@67.211.74.200) State EXECUTE
2017-06-12 11:45:30.032256 [DEBUG] mod_sofia.c:198 sofia/internal/8012790596@67.211.74.200 SOFIA EXECUTE
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:328 sofia/internal/8012790596@67.211.74.200 Standard EXECUTE
EXECUTE sofia/internal/8012790596@67.211.74.200 set(call_direction=inbound)
2017-06-12 11:45:30.032256 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [call_direction]=[inbound]
EXECUTE sofia/internal/8012790596@67.211.74.200 transfer(5001 XML pbx.domain.com)
2017-06-12 11:45:30.032256 [DEBUG] switch_ivr.c:2165 (sofia/internal/8012790596@67.211.74.200) State Change CS_EXECUTE -> CS_ROUTING
2017-06-12 11:45:30.032256 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/8012790596@67.211.74.200 to XML[5001@pbx.domain.com]
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8012790596@67.211.74.200) State EXECUTE going to sleep
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_ROUTING (Cur 1 Tot 177)
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/8012790596@67.211.74.200) State ROUTING
2017-06-12 11:45:30.032256 [DEBUG] mod_sofia.c:143 sofia/internal/8012790596@67.211.74.200 SOFIA ROUTING
2017-06-12 11:45:30.032256 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8012790596@67.211.74.200 Standard ROUTING
2017-06-12 11:45:30.032256 [INFO] mod_dialplan_xml.c:637 Processing MICHAEL JOHNSON <8012790596>->5001 in context pbx.domain.com
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->user_exists] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/8012790596@67.211.74.200 set(user_exists=false)
2017-06-12 11:45:30.052239 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [user_exists]=[false]
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->call-direction] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->variables] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->user_record] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:30.052239 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/8012790596@67.211.74.200 set(user_record=)
2017-06-12 11:45:30.052239 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [user_record]=[UNDEF]
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2017-06-12 11:45:30.072242 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:30.072242 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/8012790596@67.211.74.200 set(from_user_exists=false)
2017-06-12 11:45:30.072242 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [from_user_exists]=[false]
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->redial] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [redial] destination_number(5001) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->speed_dial] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [speed_dial] destination_number(5001) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->CentraCom.1d10] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [CentraCom.1d10] destination_number(5001) =~ /^\+?1?(\d{10})$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->CentraCom.911] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [CentraCom.911] destination_number(5001) =~ /^(911)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->agent_status] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [agent_status] destination_number(5001) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->agent_status_id] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [agent_status_id] destination_number(5001) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Canada] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Canada] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Canada] destination_number(5001) =~ /^5502$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->FrontDesk] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [FrontDesk] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [FrontDesk] destination_number(5001) =~ /^5503$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Payments] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Payments] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Payments] destination_number(5001) =~ /^5505$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Spanish_Support] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Spanish_Support] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Spanish_Support] destination_number(5001) =~ /^5501$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Support] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Support] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Support] destination_number(5001) =~ /^5500$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->WillCall] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [WillCall] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [WillCall] destination_number(5001) =~ /^5504$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->group-intercept] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [group-intercept] destination_number(5001) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->page-extension] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [page-extension] destination_number(5001) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->eavesdrop] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [eavesdrop] destination_number(5001) =~ /^\*33(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->call_privacy] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [call_privacy] destination_number(5001) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->call_return] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [call_return] destination_number(5001) =~ /^\*69$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->extension_queue] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [extension_queue] destination_number(5001) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->intercept-ext] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [intercept-ext] destination_number(5001) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [intercept-ext-polycom] destination_number(5001) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->dx] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [dx] destination_number(5001) =~ /^dx$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->att_xfer] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [att_xfer] destination_number(5001) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->extension-to-voicemail] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [extension-to-voicemail] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->send_to_voicemail] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [send_to_voicemail] destination_number(5001) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->vmain] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [vmain] destination_number(5001) =~ /^vmain$|^\*4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->xfer_vm] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [xfer_vm] destination_number(5001) =~ /^xfer_vm$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->is_transfer] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [is_transfer] destination_number(5001) =~ /^is_transfer$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->vmain_user] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [vmain_user] destination_number(5001) =~ /^\*97$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->After_Hours] continue=
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [After_Hours] destination_number(5001) =~ /^5003$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Open_Hours] continue=
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [Open_Hours] destination_number(5001) =~ /^5001$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action answer()
Dialplan: sofia/internal/8012790596@67.211.74.200 Action sleep(1000)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(ringback=local_stream://pbx.domain.com/Main_-_Thrive_Life)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(transfer_ringback=local_stream://pbx.domain.com/Main_-_Thrive_Life)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(ivr_menu_uuid=ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action ivr(ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action transfer(5503 XML pbx.domain.com)
2017-06-12 11:45:30.072242 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/8012790596@67.211.74.200) State Change CS_ROUTING -> CS_EXECUTE
2017-06-12 11:45:30.072242 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/8012790596@67.211.74.200) State ROUTING going to sleep
2017-06-12 11:45:30.072242 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_EXECUTE (Cur 1 Tot 177)
2017-06-12 11:45:30.072242 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8012790596@67.211.74.200) State EXECUTE
2017-06-12 11:45:30.072242 [DEBUG] mod_sofia.c:198 sofia/internal/8012790596@67.211.74.200 SOFIA EXECUTE
2017-06-12 11:45:30.072242 [DEBUG] switch_core_state_machine.c:328 sofia/internal/8012790596@67.211.74.200 Standard EXECUTE
EXECUTE sofia/internal/8012790596@67.211.74.200 export(origination_callee_id_name=5001)
2017-06-12 11:45:30.072242 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[5001]
EXECUTE sofia/internal/8012790596@67.211.74.200 set(RFC2822_DATE=Mon, 12 Jun 2017 11:45:30 -0600)
2017-06-12 11:45:30.072242 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [RFC2822_DATE]=[Mon, 12 Jun 2017 11:45:30 -0600]
EXECUTE sofia/internal/8012790596@67.211.74.200 hash(insert/pbx.domain.com-last_dial/8012790596/5001)
EXECUTE sofia/internal/8012790596@67.211.74.200 answer()
2017-06-12 11:45:30.072242 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/8012790596@67.211.74.200] 192.168.3.40 port 29882 -> 67.207.47.117 port 35212 codec: 0 ms: 10
2017-06-12 11:45:30.072242 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 80 bytes per 10ms
2017-06-12 11:45:30.072242 [DEBUG] switch_core_media.c:7166 sofia/internal/8012790596@67.211.74.200 Set 2833 dtmf send payload to 101
2017-06-12 11:45:30.072242 [DEBUG] switch_core_media.c:7173 sofia/internal/8012790596@67.211.74.200 Set 2833 dtmf receive payload to 101
2017-06-12 11:45:30.072242 [DEBUG] switch_core_media.c:7196 sofia/internal/8012790596@67.211.74.200 Set rtp dtmf delay to 40
2017-06-12 11:45:30.072242 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/8012790596@67.211.74.200:
v=0
o=FreeSWITCH 1497259648 1497259649 IN IP4 63.78.119.44
s=FreeSWITCH
c=IN IP4 63.78.119.44
t=0 0
m=audio 29882 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:10
a=sendrecv

2017-06-12 11:45:30.072242 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/8012790596@67.211.74.200] has been answered
2017-06-12 11:45:30.072242 [DEBUG] switch_channel.c:3772 (sofia/internal/8012790596@67.211.74.200) Callstate Change RINGING -> ACTIVE
2017-06-12 11:45:30.072242 [DEBUG] sofia.c:7048 Channel sofia/internal/8012790596@67.211.74.200 entering state [completed][200]
EXECUTE sofia/internal/8012790596@67.211.74.200 sleep(1000)
2017-06-12 11:45:30.072242 [DEBUG] sofia.c:7048 Channel sofia/internal/8012790596@67.211.74.200 entering state [ready][200]
EXECUTE sofia/internal/8012790596@67.211.74.200 set(hangup_after_bridge=true)
2017-06-12 11:45:31.092240 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/8012790596@67.211.74.200 set(ringback=local_stream://pbx.domain.com/Main_-_Thrive_Life)
2017-06-12 11:45:31.092240 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [ringback]=[local_stream://pbx.domain.com/Main_-_Thrive_Life]
EXECUTE sofia/internal/8012790596@67.211.74.200 set(transfer_ringback=local_stream://pbx.domain.com/Main_-_Thrive_Life)
2017-06-12 11:45:31.092240 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [transfer_ringback]=[local_stream://pbx.domain.com/Main_-_Thrive_Life]
EXECUTE sofia/internal/8012790596@67.211.74.200 set(ivr_menu_uuid=ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188)
2017-06-12 11:45:31.092240 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [ivr_menu_uuid]=[ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188]
EXECUTE sofia/internal/8012790596@67.211.74.200 ivr(ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188)
2017-06-12 11:45:31.092240 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:31.092240 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-exit'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-sub'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-exec-app'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-play-sound'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-back'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-top'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:880 building menu 'ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '0'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '1'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '2'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '3'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '4'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '6'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '/^(\d{2,11})$/'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '/^(\d{2,11})$/'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '/^(\d{2,11})$/'
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_menu.c:483 Executing IVR menu ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188
2017-06-12 11:45:31.092240 [DEBUG] switch_core_file.c:342 File /var/lib/freeswitch/recordings/pbx.domain.com/PHONE_TREE_During_Business_Hours_Main_Menu_-_With_Canada_REMOVED_JAPANESE.wav sample rate 44100 doesn't match requested rate 8000
2017-06-12 11:45:31.092240 [WARNING] switch_core_file.c:360 File has 2 channels, muxing to 1 channel will occur.
2017-06-12 11:45:31.092240 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 10ms
2017-06-12 11:45:31.192252 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed.
2017-06-12 11:45:37.492234 [DEBUG] switch_rtp.c:7455 RTP RECV DTMF 2:1400
2017-06-12 11:45:37.492234 [INFO] switch_channel.c:515 RECV DTMF 2:1400
2017-06-12 11:45:37.492234 [DEBUG] switch_ivr_play_say.c:1942 done playing file /var/lib/freeswitch/recordings/pbx.domain.com/PHONE_TREE_During_Business_Hours_Main_Menu_-_With_Canada_REMOVED_JAPANESE.wav
2017-06-12 11:45:37.492234 [DEBUG] switch_ivr_menu.c:377 waiting for 4/5 digits t/o 2000
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:424 digits '2'
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:577 IVR action on menu 'ba7bbc6d-5b2d-44c0-a1c4-ff5ba85ed188' matched '2' param 'transfer 5500 XML pbx.domain.com'
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:581 switch_ivr_menu_execute todo=[2]
EXECUTE sofia/internal/8012790596@67.211.74.200 transfer(5500 XML pbx.domain.com)
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr.c:2165 (sofia/internal/8012790596@67.211.74.200) State Change CS_EXECUTE -> CS_ROUTING
2017-06-12 11:45:39.492259 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/8012790596@67.211.74.200 to XML[5500@pbx.domain.com]
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:559 action regex [2] [/^(\d{2,11})$/] [0]
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:559 action regex [2] [/^(\d{2,11})$/] [0]
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:559 action regex [2] [/^(\d{2,11})$/] [0]
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_menu.c:673 exit-sound '(null)'
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8012790596@67.211.74.200) State EXECUTE going to sleep
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_ROUTING (Cur 1 Tot 177)
2017-06-12 11:45:39.492259 [DEBUG] switch_channel.c:2249 (sofia/internal/8012790596@67.211.74.200) Callstate Change ACTIVE -> RINGING
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/8012790596@67.211.74.200) State ROUTING
2017-06-12 11:45:39.492259 [DEBUG] mod_sofia.c:143 sofia/internal/8012790596@67.211.74.200 SOFIA ROUTING
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8012790596@67.211.74.200 Standard ROUTING
2017-06-12 11:45:39.492259 [INFO] mod_dialplan_xml.c:637 Processing MICHAEL JOHNSON <8012790596>->5500 in context pbx.domain.com
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->user_exists] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/8012790596@67.211.74.200 set(user_exists=false)
2017-06-12 11:45:39.492259 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [user_exists]=[false]
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->call-direction] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->variables] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->user_record] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/8012790596@67.211.74.200 set(user_record=)
2017-06-12 11:45:39.492259 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [user_record]=[UNDEF]
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:39.492259 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/8012790596@67.211.74.200 set(from_user_exists=false)
2017-06-12 11:45:39.492259 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [from_user_exists]=[false]
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->redial] continue=true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [redial] destination_number(5500) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->speed_dial] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [speed_dial] destination_number(5500) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->CentraCom.1d10] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [CentraCom.1d10] destination_number(5500) =~ /^\+?1?(\d{10})$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->CentraCom.911] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [CentraCom.911] destination_number(5500) =~ /^(911)$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->agent_status] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [agent_status] destination_number(5500) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->agent_status_id] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [agent_status_id] destination_number(5500) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Canada] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Canada] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Canada] destination_number(5500) =~ /^5502$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->FrontDesk] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [FrontDesk] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [FrontDesk] destination_number(5500) =~ /^5503$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Payments] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Payments] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Payments] destination_number(5500) =~ /^5505$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Spanish_Support] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Spanish_Support] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Spanish_Support] destination_number(5500) =~ /^5501$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 parsing [pbx.domain.com->Support] continue=false
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (FAIL) [Support] ${caller_id_name}(MICHAEL JOHNSON) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/8012790596@67.211.74.200 Regex (PASS) [Support] destination_number(5500) =~ /^5500$/ break=on-false
Dialplan: sofia/internal/8012790596@67.211.74.200 Action answer()
Dialplan: sofia/internal/8012790596@67.211.74.200 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action callcenter(Support@pbx.domain.com)
Dialplan: sofia/internal/8012790596@67.211.74.200 Action hangup()
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/8012790596@67.211.74.200) State Change CS_ROUTING -> CS_EXECUTE
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/8012790596@67.211.74.200) State ROUTING going to sleep
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_EXECUTE (Cur 1 Tot 177)
2017-06-12 11:45:39.492259 [DEBUG] switch_channel.c:2251 (sofia/internal/8012790596@67.211.74.200) Callstate Change RINGING -> ACTIVE
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8012790596@67.211.74.200) State EXECUTE
2017-06-12 11:45:39.492259 [DEBUG] mod_sofia.c:198 sofia/internal/8012790596@67.211.74.200 SOFIA EXECUTE
2017-06-12 11:45:39.492259 [DEBUG] switch_core_state_machine.c:328 sofia/internal/8012790596@67.211.74.200 Standard EXECUTE
EXECUTE sofia/internal/8012790596@67.211.74.200 export(origination_callee_id_name=5500)
2017-06-12 11:45:39.492259 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[5500]
EXECUTE sofia/internal/8012790596@67.211.74.200 set(RFC2822_DATE=Mon, 12 Jun 2017 11:45:39 -0600)
2017-06-12 11:45:39.492259 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [RFC2822_DATE]=[Mon, 12 Jun 2017 11:45:39 -0600]
EXECUTE sofia/internal/8012790596@67.211.74.200 hash(insert/pbx.domain.com-last_dial/8012790596/5500)
EXECUTE sofia/internal/8012790596@67.211.74.200 answer()
EXECUTE sofia/internal/8012790596@67.211.74.200 set(hangup_after_bridge=true)
2017-06-12 11:45:39.492259 [DEBUG] mod_dptools.c:1530 SET sofia/internal/8012790596@67.211.74.200 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/8012790596@67.211.74.200 callcenter(Support@pbx.domain.com)
2017-06-12 11:45:39.492259 [DEBUG] mod_callcenter.c:2885 Member MICHAEL JOHNSON <8012790596> joining queue Support@pbx.domain.com
2017-06-12 11:45:39.492259 [WARNING] mod_local_stream.c:831 Unknown source pbx.domain.com/Main_-_Thrive_Life, trying 'default'
2017-06-12 11:45:39.492259 [DEBUG] mod_local_stream.c:868 Opening Stream [default/8000] 8000hz
2017-06-12 11:45:39.492259 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 10ms
2017-06-12 11:45:39.512233 [DEBUG] mod_callcenter.c:1135 Updated Agent mJOHNSON@pbx.domain.com set state = Receiving
2017-06-12 11:45:39.512233 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = Receiving
2017-06-12 11:45:39.512233 [DEBUG] mod_callcenter.c:1615 Setting outbound caller_id_name to: MICHAEL JOHNSON
2017-06-12 11:45:39.512233 [DEBUG] mod_callcenter.c:1615 Setting outbound caller_id_name to: MICHAEL JOHNSON
2017-06-12 11:45:39.512233 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:45:39.512233 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:45:39.512233 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:45:39.512233 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/111@10.1.10.65:5060 [7045041d-9bce-4ecc-8af7-e9d66dc1d372]
2017-06-12 11:45:39.512233 [DEBUG] mod_sofia.c:4818 (sofia/internal/111@10.1.10.65:5060) State Change CS_NEW -> CS_INIT
2017-06-12 11:45:39.512233 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_INIT (Cur 2 Tot 178)
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/111@10.1.10.65:5060) State INIT
2017-06-12 11:45:39.512233 [DEBUG] mod_sofia.c:90 sofia/internal/111@10.1.10.65:5060 SOFIA INIT
2017-06-12 11:45:39.512233 [DEBUG] sofia_glue.c:1295 sofia/internal/111@10.1.10.65:5060 sending invite version: 1.6.17 -34-0fc0946 64bit
Local SDP:
v=0
o=FreeSWITCH 1497270419 1497270420 IN IP4 192.168.3.40
s=FreeSWITCH
c=IN IP4 192.168.3.40
t=0 0
m=audio 19120 RTP/AVP 9 0 8 3 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:40 sofia/internal/111@10.1.10.65:5060 Standard INIT
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/111@10.1.10.65:5060) State Change CS_INIT -> CS_ROUTING
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/111@10.1.10.65:5060) State INIT going to sleep
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_ROUTING (Cur 2 Tot 178)
2017-06-12 11:45:39.512233 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [calling][0]
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/111@10.1.10.65:5060) State ROUTING
2017-06-12 11:45:39.512233 [DEBUG] mod_sofia.c:143 sofia/internal/111@10.1.10.65:5060 SOFIA ROUTING
2017-06-12 11:45:39.512233 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/111@10.1.10.65:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/111@10.1.10.65:5060) State ROUTING going to sleep
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 178)
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/111@10.1.10.65:5060) State CONSUME_MEDIA
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/111@10.1.10.65:5060) State CONSUME_MEDIA going to sleep
2017-06-12 11:45:39.512233 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
2017-06-12 11:45:39.512233 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:45:39.512233 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/601@10.1.10.150:5062 [6faabab6-d842-479d-a779-e1064f2a5544]
2017-06-12 11:45:39.512233 [DEBUG] mod_sofia.c:4818 (sofia/internal/601@10.1.10.150:5062) State Change CS_NEW -> CS_INIT
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_INIT (Cur 3 Tot 179)
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/601@10.1.10.150:5062) State INIT
2017-06-12 11:45:39.512233 [DEBUG] mod_sofia.c:90 sofia/internal/601@10.1.10.150:5062 SOFIA INIT
2017-06-12 11:45:39.512233 [DEBUG] sofia_glue.c:1295 sofia/internal/601@10.1.10.150:5062 sending invite version: 1.6.17 -34-0fc0946 64bit
Local SDP:
v=0
o=FreeSWITCH 1497266725 1497266726 IN IP4 192.168.3.40
s=FreeSWITCH
c=IN IP4 192.168.3.40
t=0 0
m=audio 22814 RTP/AVP 9 0 8 3 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:40 sofia/internal/601@10.1.10.150:5062 Standard INIT
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/601@10.1.10.150:5062) State Change CS_INIT -> CS_ROUTING
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/601@10.1.10.150:5062) State INIT going to sleep
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_ROUTING (Cur 3 Tot 179)
2017-06-12 11:45:39.512233 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [calling][0]
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/601@10.1.10.150:5062) State ROUTING
2017-06-12 11:45:39.512233 [DEBUG] mod_sofia.c:143 sofia/internal/601@10.1.10.150:5062 SOFIA ROUTING
2017-06-12 11:45:39.512233 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/601@10.1.10.150:5062) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/601@10.1.10.150:5062) State ROUTING going to sleep
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 179)
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA
2017-06-12 11:45:39.512233 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA going to sleep
2017-06-12 11:45:39.572240 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [proceeding][180]
2017-06-12 11:45:39.572240 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/111@10.1.10.65:5060!
2017-06-12 11:45:39.572240 [DEBUG] switch_channel.c:3345 (sofia/internal/111@10.1.10.65:5060) Callstate Change DOWN -> RINGING
2017-06-12 11:45:39.772254 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [proceeding][180]
2017-06-12 11:45:39.772254 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/601@10.1.10.150:5062!
2017-06-12 11:45:39.772254 [DEBUG] switch_channel.c:3345 (sofia/internal/601@10.1.10.150:5062) Callstate Change DOWN -> RINGING
2017-06-12 11:45:44.672235 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [completing][200]
2017-06-12 11:45:44.672235 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20167 20167 IN IP4 10.1.10.65
s=SDP data
c=IN IP4 10.1.10.65
t=0 0
m=audio 12158 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:45:44.672235 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [ready][200]
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/111@10.1.10.65:5060 G722/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-12 11:45:44.672235 [DEBUG] switch_core_codec.c:111 sofia/internal/111@10.1.10.65:5060 Original read codec set to G722:9
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:4754 sofia/internal/111@10.1.10.65:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/111@10.1.10.65:5060] 192.168.3.40 port 19120 -> 10.1.10.65 port 12158 codec: 9 ms: 20
2017-06-12 11:45:44.672235 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:7166 sofia/internal/111@10.1.10.65:5060 Set 2833 dtmf send payload to 101
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:7173 sofia/internal/111@10.1.10.65:5060 Set 2833 dtmf receive payload to 101
2017-06-12 11:45:44.672235 [DEBUG] switch_core_media.c:7196 sofia/internal/111@10.1.10.65:5060 Set rtp dtmf delay to 40
2017-06-12 11:45:44.672235 [NOTICE] sofia.c:8182 Channel [sofia/internal/111@10.1.10.65:5060] has been answered
2017-06-12 11:45:44.672235 [DEBUG] switch_channel.c:3772 (sofia/internal/111@10.1.10.65:5060) Callstate Change RINGING -> ACTIVE
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/111@10.1.10.65:5060]
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/111@10.1.10.65:5060]
2017-06-12 11:45:44.692241 [NOTICE] switch_core_session.c:249 Hangup sofia/internal/601@10.1.10.150:5062 [CS_CONSUME_MEDIA] [LOSE_RACE]
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_HANGUP (Cur 3 Tot 179)
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/601@10.1.10.150:5062) Callstate Change RINGING -> HANGUP
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/601@10.1.10.150:5062) State HANGUP
2017-06-12 11:45:44.692241 [DEBUG] mod_sofia.c:438 Channel sofia/internal/601@10.1.10.150:5062 hanging up, cause: LOSE_RACE
2017-06-12 11:45:44.692241 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/601@10.1.10.150:5062
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:60 sofia/internal/601@10.1.10.150:5062 Standard HANGUP, cause: LOSE_RACE
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/601@10.1.10.150:5062) State HANGUP going to sleep
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/601@10.1.10.150:5062) State Change CS_HANGUP -> CS_REPORTING
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_REPORTING (Cur 3 Tot 179)
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/601@10.1.10.150:5062) State REPORTING
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_originate.c:3833 Originate Resulted in Error Cause: 502 [LOSE_RACE]
2017-06-12 11:45:44.692241 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [user] cause: [LOSE_RACE]
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_originate.c:3833 Originate Resulted in Error Cause: 502 [LOSE_RACE]
2017-06-12 11:45:44.692241 [DEBUG] mod_callcenter.c:1951 Agent tester@pbx.domain.com Origination Canceled : LOSE_RACE
2017-06-12 11:45:44.692241 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set ready_time = 1497289574
2017-06-12 11:45:44.692241 [DEBUG] mod_callcenter.c:1996 Agent tester@pbx.domain.com sleeping for 30 seconds
2017-06-12 11:45:44.692241 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = Waiting
2017-06-12 11:45:44.692241 [DEBUG] switch_core_media_bug.c:828 Attaching BUG to sofia/internal/8012790596@67.211.74.200
2017-06-12 11:45:44.692241 [DEBUG] mod_callcenter.c:1798 Agent mJOHNSON@pbx.domain.com answered "MICHAEL JOHNSON" <8012790596> from queue Support@pbx.domain.com (Recorded)
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_bridge.c:2017 (sofia/internal/8012790596@67.211.74.200) State Change CS_EXECUTE -> CS_HIBERNATE
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_bridge.c:2019 (sofia/internal/111@10.1.10.65:5060) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_HIBERNATE (Cur 3 Tot 179)
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/111@10.1.10.65:5060) State HIBERNATE
2017-06-12 11:45:44.692241 [DEBUG] mod_sofia.c:180 sofia/internal/111@10.1.10.65:5060 SOFIA HIBERNATE
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_bridge.c:971 (sofia/internal/111@10.1.10.65:5060) State Change CS_HIBERNATE -> CS_RESET
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/111@10.1.10.65:5060) State HIBERNATE going to sleep
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_RESET (Cur 3 Tot 179)
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/111@10.1.10.65:5060) State RESET
2017-06-12 11:45:44.692241 [DEBUG] mod_sofia.c:161 sofia/internal/111@10.1.10.65:5060 SOFIA RESET
2017-06-12 11:45:44.692241 [DEBUG] switch_ivr_bridge.c:956 sofia/internal/111@10.1.10.65:5060 CUSTOM RESET
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:188 sofia/internal/111@10.1.10.65:5060 Standard RESET
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/111@10.1.10.65:5060) State RESET going to sleep
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:174 sofia/internal/601@10.1.10.150:5062 Standard REPORTING, cause: LOSE_RACE
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/601@10.1.10.150:5062) State REPORTING going to sleep
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/601@10.1.10.150:5062) State Change CS_REPORTING -> CS_DESTROY
2017-06-12 11:45:44.692241 [DEBUG] switch_core_session.c:1664 Session 179 (sofia/internal/601@10.1.10.150:5062) Locked, Waiting on external entities
2017-06-12 11:45:44.692241 [NOTICE] switch_core_session.c:1682 Session 179 (sofia/internal/601@10.1.10.150:5062) Ended
2017-06-12 11:45:44.692241 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/601@10.1.10.150:5062 [CS_DESTROY]
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_DESTROY (Cur 2 Tot 179)
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/601@10.1.10.150:5062) State DESTROY
2017-06-12 11:45:44.692241 [DEBUG] mod_sofia.c:343 sofia/internal/601@10.1.10.150:5062 SOFIA DESTROY
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:181 sofia/internal/601@10.1.10.150:5062 Standard DESTROY
2017-06-12 11:45:44.692241 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/601@10.1.10.150:5062) State DESTROY going to sleep
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_async.c:1500 No silence detection configured; assuming start of speech
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_play_say.c:1942 done playing file local_stream://pbx.domain.com/Main_-_Thrive_Life
2017-06-12 11:45:44.712234 [DEBUG] mod_callcenter.c:3050 Member MICHAEL JOHNSON <8012790596> is answered by an agent in queue Support@pbx.domain.com
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/8012790596@67.211.74.200) State EXECUTE going to sleep
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_HIBERNATE (Cur 2 Tot 179)
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/8012790596@67.211.74.200) State HIBERNATE
2017-06-12 11:45:44.712234 [DEBUG] mod_sofia.c:180 sofia/internal/8012790596@67.211.74.200 SOFIA HIBERNATE
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_bridge.c:971 (sofia/internal/8012790596@67.211.74.200) State Change CS_HIBERNATE -> CS_RESET
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/8012790596@67.211.74.200) State HIBERNATE going to sleep
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_RESET (Cur 2 Tot 179)
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/8012790596@67.211.74.200) State RESET
2017-06-12 11:45:44.712234 [DEBUG] mod_sofia.c:161 sofia/internal/8012790596@67.211.74.200 SOFIA RESET
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_bridge.c:956 sofia/internal/8012790596@67.211.74.200 CUSTOM RESET
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_bridge.c:963 (sofia/internal/8012790596@67.211.74.200) State Change CS_RESET -> CS_SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/8012790596@67.211.74.200) State RESET going to sleep
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 179)
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/8012790596@67.211.74.200) State SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_bridge.c:981 sofia/internal/8012790596@67.211.74.200 CUSTOM SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_bridge.c:1013 (sofia/internal/111@10.1.10.65:5060) State Change CS_RESET -> CS_SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_SOFT_EXECUTE (Cur 2 Tot 179)
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/111@10.1.10.65:5060) State SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_ivr_bridge.c:981 sofia/internal/111@10.1.10.65:5060 CUSTOM SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:400 sofia/internal/111@10.1.10.65:5060 Standard SOFT_EXECUTE
2017-06-12 11:45:44.712234 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/111@10.1.10.65:5060) State SOFT_EXECUTE going to sleep
2017-06-12 11:45:44.732262 [DEBUG] switch_ivr_bridge.c:1496 (sofia/internal/111@10.1.10.65:5060) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
2017-06-12 11:45:44.732262 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 179)
2017-06-12 11:45:44.732262 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/111@10.1.10.65:5060) State CONSUME_MEDIA
2017-06-12 11:45:44.732262 [DEBUG] switch_ivr_bridge.c:920 sofia/internal/111@10.1.10.65:5060 CUSTOM HOLD
2017-06-12 11:45:44.732262 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/111@10.1.10.65:5060) State CONSUME_MEDIA going to sleep
2017-06-12 11:45:44.732262 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/111@10.1.10.65:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-06-12 11:45:44.732262 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 179)
2017-06-12 11:45:44.732262 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/111@10.1.10.65:5060) State EXCHANGE_MEDIA
2017-06-12 11:45:44.732262 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2017-06-12 11:45:44.732262 [NOTICE] switch_core_io.c:1202 Activating write resampler
2017-06-12 11:45:44.732262 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 160 bytes to accommodate 320->160
2017-06-12 11:45:44.732262 [DEBUG] mod_callcenter.c:1842 Member "MICHAEL JOHNSON" 8012790596 is bridged to agent mJOHNSON@pbx.domain.com
2017-06-12 11:45:44.732262 [DEBUG] mod_callcenter.c:1256 Updated tier: Agent mJOHNSON@pbx.domain.com in Queue Support@pbx.domain.com set state = Active Inbound
2017-06-12 11:45:44.732262 [DEBUG] mod_callcenter.c:1135 Updated Agent mJOHNSON@pbx.domain.com set state = In a queue call
2017-06-12 11:45:44.732262 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2017-06-12 11:45:44.732262 [NOTICE] switch_core_io.c:1202 Activating write resampler
2017-06-12 11:45:44.732262 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 640 bytes to accommodate 320->640
2017-06-12 11:45:44.772495 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [calling][0]
2017-06-12 11:45:44.772495 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [ready][200]
2017-06-12 11:45:44.772495 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20167 20168 IN IP4 10.1.10.65
s=SDP data
c=IN IP4 10.1.10.65
t=0 0
m=audio 12158 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:4754 sofia/internal/111@10.1.10.65:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:45:44.772495 [DEBUG] sofia.c:8025 Processing updated SDP
2017-06-12 11:45:44.772495 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/111@10.1.10.65:5060.
2017-06-12 11:45:44.892257 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed.
2017-06-12 11:45:48.012237 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [received][100]
2017-06-12 11:45:48.012237 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20167 20169 IN IP4 10.1.10.65
s=SDP data
c=IN IP4 10.1.10.65
t=0 0
m=audio 12158 RTP/AVP 9 0 8 18 105 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:105 G726-40/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20

2017-06-12 11:45:48.012237 [DEBUG] switch_channel.c:1844 (sofia/internal/111@10.1.10.65:5060) Callstate Change ACTIVE -> HELD
2017-06-12 11:45:48.072237 [DEBUG] switch_ivr.c:623 sofia/internal/8012790596@67.211.74.200 Command Execute playback(local_stream://default)
EXECUTE sofia/internal/8012790596@67.211.74.200 playback(local_stream://default)
2017-06-12 11:45:48.072237 [DEBUG] mod_local_stream.c:868 Opening Stream [default/8000] 8000hz
2017-06-12 11:45:48.072237 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 10ms
2017-06-12 11:45:48.092284 [NOTICE] switch_core_io.c:1229 Deactivating write resampler
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:4754 sofia/internal/111@10.1.10.65:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:45:48.252238 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/111@10.1.10.65:5060.
2017-06-12 11:45:48.252238 [DEBUG] sofia.c:7963 Processing updated SDP
2017-06-12 11:45:48.272239 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [completed][200]
2017-06-12 11:45:48.272239 [DEBUG] sofia.c:7048 Channel sofia/internal/111@10.1.10.65:5060 entering state [ready][200]
2017-06-12 11:45:50.772237 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/111@pbx.domain.com:5060 [61fbdb67-d782-474f-9e42-a2ea9460e71b]
2017-06-12 11:45:50.772237 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_NEW (Cur 3 Tot 180)
2017-06-12 11:45:50.772237 [DEBUG] sofia.c:9834 sofia/internal/111@pbx.domain.com:5060 receiving invite from 10.1.10.65:5060 version: 1.6.17 -34-0fc0946 64bit
2017-06-12 11:45:50.772237 [DEBUG] sofia.c:10005 IP 10.1.10.65 Rejected by acl "domains". Falling back to Digest auth.
2017-06-12 11:45:50.772237 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [5505@pbx.domain.com] from ip 10.1.10.65
2017-06-12 11:45:50.772237 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/111@pbx.domain.com:5060) State NEW
2017-06-12 11:45:50.772237 [DEBUG] sofia.c:2334 detaching session 61fbdb67-d782-474f-9e42-a2ea9460e71b
2017-06-12 11:45:50.792253 [DEBUG] sofia.c:2442 Re-attaching to session 61fbdb67-d782-474f-9e42-a2ea9460e71b
2017-06-12 11:45:50.792253 [DEBUG] sofia.c:9834 sofia/internal/111@pbx.domain.com:5060 receiving invite from 10.1.10.65:5060 version: 1.6.17 -34-0fc0946 64bit
2017-06-12 11:45:50.792253 [DEBUG] sofia.c:10005 IP 10.1.10.65 Rejected by acl "domains". Falling back to Digest auth.
2017-06-12 11:45:50.792253 [DEBUG] sofia.c:7048 Channel sofia/internal/111@pbx.domain.com:5060 entering state [received][100]
2017-06-12 11:45:50.792253 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20168 20168 IN IP4 10.1.10.65
s=SDP data
c=IN IP4 10.1.10.65
t=0 0
m=audio 12162 RTP/AVP 9 0 8 18 105 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:105 G726-40/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-40:105:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/111@pbx.domain.com:5060 G722/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-12 11:45:50.792253 [DEBUG] switch_core_codec.c:111 sofia/internal/111@pbx.domain.com:5060 Original read codec set to G722:9
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:45:50.792253 [DEBUG] switch_core_media.c:4754 sofia/internal/111@pbx.domain.com:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:45:50.792253 [DEBUG] sofia.c:7471 (sofia/internal/111@pbx.domain.com:5060) State Change CS_NEW -> CS_INIT
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_INIT (Cur 3 Tot 180)
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/111@pbx.domain.com:5060) State INIT
2017-06-12 11:45:50.792253 [DEBUG] mod_sofia.c:90 sofia/internal/111@pbx.domain.com:5060 SOFIA INIT
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:40 sofia/internal/111@pbx.domain.com:5060 Standard INIT
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/111@pbx.domain.com:5060) State Change CS_INIT -> CS_ROUTING
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/111@pbx.domain.com:5060) State INIT going to sleep
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_ROUTING (Cur 3 Tot 180)
2017-06-12 11:45:50.792253 [DEBUG] switch_channel.c:2249 (sofia/internal/111@pbx.domain.com:5060) Callstate Change DOWN -> RINGING
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/111@pbx.domain.com:5060) State ROUTING
2017-06-12 11:45:50.792253 [DEBUG] mod_sofia.c:143 sofia/internal/111@pbx.domain.com:5060 SOFIA ROUTING
2017-06-12 11:45:50.792253 [DEBUG] switch_core_state_machine.c:236 sofia/internal/111@pbx.domain.com:5060 Standard ROUTING
2017-06-12 11:45:50.792253 [INFO] mod_dialplan_xml.c:637 Processing Mike JOHNSON <111>->5505 in context pbx.domain.com
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->user_exists] continue=true
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
2017-06-12 11:45:50.812238 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:50.812238 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(user_exists=false)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [user_exists]=[false]
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->call-direction] continue=true
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 ANTI-Action set(call_direction=local)
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->variables] continue=true
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->user_record] continue=true
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
2017-06-12 11:45:50.812238 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:50.812238 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
2017-06-12 11:45:50.812238 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f219005f3b0 Connected.
2017-06-12 11:45:50.812238 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f219005f3b0 released.
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(user_record=)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [user_record]=[UNDEF]
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(from_user_exists=true)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [from_user_exists]=[true]
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(from_user_record=all)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [from_user_record]=[all]
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(record_session=true) INLINE
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(record_session=true)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [record_session]=[true]
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action export(nolocal:api_on_answer=uuid_record ${uuid} start ${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext})
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->redial] continue=true
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [redial] destination_number(5505) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->speed_dial] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [speed_dial] destination_number(5505) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->CentraCom.1d10] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [CentraCom.1d10] destination_number(5505) =~ /^\+?1?(\d{10})$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->CentraCom.911] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [CentraCom.911] destination_number(5505) =~ /^(911)$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->agent_status] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [agent_status] destination_number(5505) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->agent_status_id] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [agent_status_id] destination_number(5505) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->Canada] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [Canada] ${caller_id_name}(111) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [Canada] destination_number(5505) =~ /^5502$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->FrontDesk] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [FrontDesk] ${caller_id_name}(111) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [FrontDesk] destination_number(5505) =~ /^5503$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 parsing [pbx.domain.com->Payments] continue=false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (FAIL) [Payments] ${caller_id_name}(111) =~ /^([^#]+#)(.*)$/ break=never
Dialplan: sofia/internal/111@pbx.domain.com:5060 Regex (PASS) [Payments] destination_number(5505) =~ /^5505$/ break=on-false
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action answer()
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action callcenter(Payments@pbx.domain.com)
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action transfer(5500 XML pbx.domain.com)
Dialplan: sofia/internal/111@pbx.domain.com:5060 Action hangup()
2017-06-12 11:45:50.812238 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/111@pbx.domain.com:5060) State Change CS_ROUTING -> CS_EXECUTE
2017-06-12 11:45:50.812238 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/111@pbx.domain.com:5060) State ROUTING going to sleep
2017-06-12 11:45:50.812238 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_EXECUTE (Cur 3 Tot 180)
2017-06-12 11:45:50.812238 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/111@pbx.domain.com:5060) State EXECUTE
2017-06-12 11:45:50.812238 [DEBUG] mod_sofia.c:198 sofia/internal/111@pbx.domain.com:5060 SOFIA EXECUTE
2017-06-12 11:45:50.812238 [DEBUG] switch_core_state_machine.c:328 sofia/internal/111@pbx.domain.com:5060 Standard EXECUTE
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(call_direction=local)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [call_direction]=[local]
EXECUTE sofia/internal/111@pbx.domain.com:5060 export(origination_callee_id_name=5505)
2017-06-12 11:45:50.812238 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[5505]
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(RFC2822_DATE=Mon, 12 Jun 2017 11:45:50 -0600)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [RFC2822_DATE]=[Mon, 12 Jun 2017 11:45:50 -0600]
EXECUTE sofia/internal/111@pbx.domain.com:5060 export(nolocal:api_on_answer=uuid_record 61fbdb67-d782-474f-9e42-a2ea9460e71b start /var/lib/freeswitch/recordings/pbx.domain.com/archive/2017/Jun/12/61fbdb67-d782-474f-9e42-a2ea9460e71b.wav)
2017-06-12 11:45:50.812238 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [api_on_answer]=[uuid_record 61fbdb67-d782-474f-9e42-a2ea9460e71b start /var/lib/freeswitch/recordings/pbx.domain.com/archive/2017/Jun/12/61fbdb67-d782-474f-9e42-a2ea9460e71b.wav]
EXECUTE sofia/internal/111@pbx.domain.com:5060 hash(insert/pbx.domain.com-last_dial/111/5505)
EXECUTE sofia/internal/111@pbx.domain.com:5060 answer()
2017-06-12 11:45:50.812238 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/111@pbx.domain.com:5060] 192.168.3.40 port 22828 -> 10.1.10.65 port 12162 codec: 9 ms: 20
2017-06-12 11:45:50.812238 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
2017-06-12 11:45:50.812238 [DEBUG] switch_core_media.c:7166 sofia/internal/111@pbx.domain.com:5060 Set 2833 dtmf send payload to 101
2017-06-12 11:45:50.812238 [DEBUG] switch_core_media.c:7173 sofia/internal/111@pbx.domain.com:5060 Set 2833 dtmf receive payload to 101
2017-06-12 11:45:50.812238 [DEBUG] switch_core_media.c:7196 sofia/internal/111@pbx.domain.com:5060 Set rtp dtmf delay to 40
2017-06-12 11:45:50.812238 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/111@pbx.domain.com:5060:
v=0
o=FreeSWITCH 1497266722 1497266723 IN IP4 192.168.3.40
s=FreeSWITCH
c=IN IP4 192.168.3.40
t=0 0
m=audio 22828 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2017-06-12 11:45:50.812238 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/111@pbx.domain.com:5060] has been answered
2017-06-12 11:45:50.812238 [DEBUG] switch_channel.c:3772 (sofia/internal/111@pbx.domain.com:5060) Callstate Change RINGING -> ACTIVE
2017-06-12 11:45:50.812238 [DEBUG] sofia.c:7048 Channel sofia/internal/111@pbx.domain.com:5060 entering state [completed][200]
EXECUTE sofia/internal/111@pbx.domain.com:5060 set(hangup_after_bridge=true)
2017-06-12 11:45:50.812238 [DEBUG] mod_dptools.c:1530 SET sofia/internal/111@pbx.domain.com:5060 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/111@pbx.domain.com:5060 callcenter(Payments@pbx.domain.com)
2017-06-12 11:45:50.812238 [DEBUG] mod_callcenter.c:2885 Member 111 <111> joining queue Payments@pbx.domain.com
2017-06-12 11:45:50.812238 [WARNING] mod_local_stream.c:831 Unknown source pbx.domain.com/Main_-_Thrive_Life, trying 'default'
2017-06-12 11:45:50.812238 [DEBUG] mod_local_stream.c:868 Opening Stream [default/16000] 16000hz
2017-06-12 11:45:50.812238 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
2017-06-12 11:45:50.832258 [DEBUG] sofia.c:7048 Channel sofia/internal/111@pbx.domain.com:5060 entering state [ready][200]
2017-06-12 11:45:50.972258 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed.
2017-06-12 11:46:14.092252 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = Receiving
2017-06-12 11:46:14.092252 [DEBUG] mod_callcenter.c:1615 Setting outbound caller_id_name to: Mike JOHNSON
2017-06-12 11:46:14.092252 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:46:14.092252 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:46:14.092252 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/601@10.1.10.150:5062 [31be99d0-f54d-4dc6-87b8-f0bc971ec380]
2017-06-12 11:46:14.092252 [DEBUG] mod_sofia.c:4818 (sofia/internal/601@10.1.10.150:5062) State Change CS_NEW -> CS_INIT
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_INIT (Cur 4 Tot 181)
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/601@10.1.10.150:5062) State INIT
2017-06-12 11:46:14.092252 [DEBUG] mod_sofia.c:90 sofia/internal/601@10.1.10.150:5062 SOFIA INIT
2017-06-12 11:46:14.092252 [DEBUG] sofia_glue.c:1295 sofia/internal/601@10.1.10.150:5062 sending invite version: 1.6.17 -34-0fc0946 64bit
Local SDP:
v=0
o=FreeSWITCH 1497262848 1497262849 IN IP4 192.168.3.40
s=FreeSWITCH
c=IN IP4 192.168.3.40
t=0 0
m=audio 26726 RTP/AVP 9 0 8 3 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:40 sofia/internal/601@10.1.10.150:5062 Standard INIT
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/601@10.1.10.150:5062) State Change CS_INIT -> CS_ROUTING
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/601@10.1.10.150:5062) State INIT going to sleep
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_ROUTING (Cur 4 Tot 181)
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/601@10.1.10.150:5062) State ROUTING
2017-06-12 11:46:14.092252 [DEBUG] mod_sofia.c:143 sofia/internal/601@10.1.10.150:5062 SOFIA ROUTING
2017-06-12 11:46:14.092252 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/601@10.1.10.150:5062) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/601@10.1.10.150:5062) State ROUTING going to sleep
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 181)
2017-06-12 11:46:14.092252 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [calling][0]
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA
2017-06-12 11:46:14.092252 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA going to sleep
2017-06-12 11:46:14.212251 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set contact = {call_timeout=15,sip_invite_domain=pbx.domain.com}user/601@pbx.domain.com
2017-06-12 11:46:14.232257 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [proceeding][180]
2017-06-12 11:46:14.232257 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/601@10.1.10.150:5062!
2017-06-12 11:46:14.232257 [DEBUG] switch_channel.c:3345 (sofia/internal/601@10.1.10.150:5062) Callstate Change DOWN -> RINGING
2017-06-12 11:46:14.252242 [NOTICE] switch_core_session.c:249 Hangup sofia/internal/601@10.1.10.150:5062 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_HANGUP (Cur 4 Tot 181)
2017-06-12 11:46:14.252242 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set status = Logged Out
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/601@10.1.10.150:5062) Callstate Change RINGING -> HANGUP
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/601@10.1.10.150:5062) State HANGUP
2017-06-12 11:46:14.252242 [DEBUG] mod_sofia.c:438 Channel sofia/internal/601@10.1.10.150:5062 hanging up, cause: ORIGINATOR_CANCEL
2017-06-12 11:46:14.252242 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/601@10.1.10.150:5062
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:60 sofia/internal/601@10.1.10.150:5062 Standard HANGUP, cause: ORIGINATOR_CANCEL
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/601@10.1.10.150:5062) State HANGUP going to sleep
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/601@10.1.10.150:5062) State Change CS_HANGUP -> CS_REPORTING
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_REPORTING (Cur 4 Tot 181)
2017-06-12 11:46:14.252242 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/601@10.1.10.150:5062) State REPORTING
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:174 sofia/internal/601@10.1.10.150:5062 Standard REPORTING, cause: ORIGINATOR_CANCEL
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/601@10.1.10.150:5062) State REPORTING going to sleep
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/601@10.1.10.150:5062) State Change CS_REPORTING -> CS_DESTROY
2017-06-12 11:46:14.272244 [DEBUG] switch_core_session.c:1664 Session 181 (sofia/internal/601@10.1.10.150:5062) Locked, Waiting on external entities
2017-06-12 11:46:14.272244 [DEBUG] switch_ivr_originate.c:3833 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2017-06-12 11:46:14.272244 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
2017-06-12 11:46:14.272244 [DEBUG] switch_ivr_originate.c:3833 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2017-06-12 11:46:14.272244 [NOTICE] switch_core_session.c:1682 Session 181 (sofia/internal/601@10.1.10.150:5062) Ended
2017-06-12 11:46:14.272244 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/601@10.1.10.150:5062 [CS_DESTROY]
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_DESTROY (Cur 3 Tot 181)
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/601@10.1.10.150:5062) State DESTROY
2017-06-12 11:46:14.272244 [DEBUG] mod_sofia.c:343 sofia/internal/601@10.1.10.150:5062 SOFIA DESTROY
2017-06-12 11:46:14.272244 [DEBUG] mod_callcenter.c:1951 Agent tester@pbx.domain.com Origination Canceled : ORIGINATOR_CANCEL
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:181 sofia/internal/601@10.1.10.150:5062 Standard DESTROY
2017-06-12 11:46:14.272244 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/601@10.1.10.150:5062) State DESTROY going to sleep
2017-06-12 11:46:14.272244 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = Waiting
2017-06-12 11:46:14.292233 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set reject_delay_time = 90
2017-06-12 11:46:14.332236 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set busy_delay_time = 90
2017-06-12 11:46:14.372252 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set no_answer_delay_time = 30
2017-06-12 11:46:14.412251 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set max_no_answer = 0
2017-06-12 11:46:14.452252 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set wrap_up_time = 90
2017-06-12 11:46:19.332235 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set contact = {call_timeout=15,sip_invite_domain=pbx.domain.com}user/601@pbx.domain.com
2017-06-12 11:46:19.372235 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set status = Available
2017-06-12 11:46:19.412242 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = Receiving
2017-06-12 11:46:19.412242 [DEBUG] mod_callcenter.c:1615 Setting outbound caller_id_name to: Mike JOHNSON
2017-06-12 11:46:19.412242 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:46:19.412242 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-06-12 11:46:19.412242 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/601@10.1.10.150:5062 [b80d97e1-ca90-4cf4-a030-2c32baf23c18]
2017-06-12 11:46:19.412242 [DEBUG] mod_sofia.c:4818 (sofia/internal/601@10.1.10.150:5062) State Change CS_NEW -> CS_INIT
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_INIT (Cur 4 Tot 182)
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/601@10.1.10.150:5062) State INIT
2017-06-12 11:46:19.412242 [DEBUG] mod_sofia.c:90 sofia/internal/601@10.1.10.150:5062 SOFIA INIT
2017-06-12 11:46:19.412242 [DEBUG] sofia_glue.c:1295 sofia/internal/601@10.1.10.150:5062 sending invite version: 1.6.17 -34-0fc0946 64bit
Local SDP:
v=0
o=FreeSWITCH 1497258613 1497258614 IN IP4 192.168.3.40
s=FreeSWITCH
c=IN IP4 192.168.3.40
t=0 0
m=audio 30966 RTP/AVP 9 0 8 3 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:40 sofia/internal/601@10.1.10.150:5062 Standard INIT
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/601@10.1.10.150:5062) State Change CS_INIT -> CS_ROUTING
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/601@10.1.10.150:5062) State INIT going to sleep
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_ROUTING (Cur 4 Tot 182)
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/601@10.1.10.150:5062) State ROUTING
2017-06-12 11:46:19.412242 [DEBUG] mod_sofia.c:143 sofia/internal/601@10.1.10.150:5062 SOFIA ROUTING
2017-06-12 11:46:19.412242 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/601@10.1.10.150:5062) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/601@10.1.10.150:5062) State ROUTING going to sleep
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 182)
2017-06-12 11:46:19.412242 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [calling][0]
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA
2017-06-12 11:46:19.412242 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA going to sleep
2017-06-12 11:46:19.412242 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set reject_delay_time = 90
2017-06-12 11:46:19.452234 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set busy_delay_time = 90
2017-06-12 11:46:19.492258 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set no_answer_delay_time = 30
2017-06-12 11:46:19.532238 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [proceeding][180]
2017-06-12 11:46:19.532238 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/601@10.1.10.150:5062!
2017-06-12 11:46:19.532238 [DEBUG] switch_channel.c:3345 (sofia/internal/601@10.1.10.150:5062) Callstate Change DOWN -> RINGING
2017-06-12 11:46:19.532238 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set max_no_answer = 0
2017-06-12 11:46:19.572253 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set wrap_up_time = 90
2017-06-12 11:46:23.432249 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [completing][200]
2017-06-12 11:46:23.432249 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20000 20000 IN IP4 10.1.10.150
s=SDP data
c=IN IP4 10.1.10.150
t=0 0
a=sendrecv
m=audio 11780 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:46:23.432249 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [ready][200]
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/601@10.1.10.150:5062 G722/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-12 11:46:23.432249 [DEBUG] switch_core_codec.c:111 sofia/internal/601@10.1.10.150:5062 Original read codec set to G722:9
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:4754 sofia/internal/601@10.1.10.150:5062 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/601@10.1.10.150:5062] 192.168.3.40 port 30966 -> 10.1.10.150 port 11780 codec: 9 ms: 20
2017-06-12 11:46:23.432249 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:7166 sofia/internal/601@10.1.10.150:5062 Set 2833 dtmf send payload to 101
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:7173 sofia/internal/601@10.1.10.150:5062 Set 2833 dtmf receive payload to 101
2017-06-12 11:46:23.432249 [DEBUG] switch_core_media.c:7196 sofia/internal/601@10.1.10.150:5062 Set rtp dtmf delay to 40
2017-06-12 11:46:23.432249 [NOTICE] sofia.c:8182 Channel [sofia/internal/601@10.1.10.150:5062] has been answered
2017-06-12 11:46:23.432249 [DEBUG] switch_channel.c:3772 (sofia/internal/601@10.1.10.150:5062) Callstate Change RINGING -> ACTIVE
2017-06-12 11:46:23.432249 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/601@10.1.10.150:5062]
2017-06-12 11:46:23.432249 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/601@10.1.10.150:5062]
2017-06-12 11:46:23.432249 [DEBUG] mod_callcenter.c:1798 Agent tester@pbx.domain.com answered "111" <111> from queue Payments@pbx.domain.com
2017-06-12 11:46:23.432249 [DEBUG] switch_ivr_bridge.c:2017 (sofia/internal/111@pbx.domain.com:5060) State Change CS_EXECUTE -> CS_HIBERNATE
2017-06-12 11:46:23.432249 [DEBUG] switch_ivr_bridge.c:2019 (sofia/internal/601@10.1.10.150:5062) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_HIBERNATE (Cur 4 Tot 182)
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/601@10.1.10.150:5062) State HIBERNATE
2017-06-12 11:46:23.432249 [DEBUG] mod_sofia.c:180 sofia/internal/601@10.1.10.150:5062 SOFIA HIBERNATE
2017-06-12 11:46:23.432249 [DEBUG] switch_ivr_bridge.c:971 (sofia/internal/601@10.1.10.150:5062) State Change CS_HIBERNATE -> CS_RESET
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/601@10.1.10.150:5062) State HIBERNATE going to sleep
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_RESET (Cur 4 Tot 182)
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/601@10.1.10.150:5062) State RESET
2017-06-12 11:46:23.432249 [DEBUG] mod_sofia.c:161 sofia/internal/601@10.1.10.150:5062 SOFIA RESET
2017-06-12 11:46:23.432249 [DEBUG] switch_ivr_bridge.c:956 sofia/internal/601@10.1.10.150:5062 CUSTOM RESET
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:188 sofia/internal/601@10.1.10.150:5062 Standard RESET
2017-06-12 11:46:23.432249 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/601@10.1.10.150:5062) State RESET going to sleep
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_play_say.c:1942 done playing file local_stream://pbx.domain.com/Main_-_Thrive_Life
2017-06-12 11:46:23.452235 [DEBUG] mod_callcenter.c:3050 Member 111 <111> is answered by an agent in queue Payments@pbx.domain.com
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/111@pbx.domain.com:5060) State EXECUTE going to sleep
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_HIBERNATE (Cur 4 Tot 182)
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/111@pbx.domain.com:5060) State HIBERNATE
2017-06-12 11:46:23.452235 [DEBUG] mod_sofia.c:180 sofia/internal/111@pbx.domain.com:5060 SOFIA HIBERNATE
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_bridge.c:971 (sofia/internal/111@pbx.domain.com:5060) State Change CS_HIBERNATE -> CS_RESET
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/111@pbx.domain.com:5060) State HIBERNATE going to sleep
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_RESET (Cur 4 Tot 182)
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/111@pbx.domain.com:5060) State RESET
2017-06-12 11:46:23.452235 [DEBUG] mod_sofia.c:161 sofia/internal/111@pbx.domain.com:5060 SOFIA RESET
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_bridge.c:956 sofia/internal/111@pbx.domain.com:5060 CUSTOM RESET
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_bridge.c:963 (sofia/internal/111@pbx.domain.com:5060) State Change CS_RESET -> CS_SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/111@pbx.domain.com:5060) State RESET going to sleep
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_SOFT_EXECUTE (Cur 4 Tot 182)
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/111@pbx.domain.com:5060) State SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_bridge.c:981 sofia/internal/111@pbx.domain.com:5060 CUSTOM SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_bridge.c:1013 (sofia/internal/601@10.1.10.150:5062) State Change CS_RESET -> CS_SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_SOFT_EXECUTE (Cur 4 Tot 182)
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/601@10.1.10.150:5062) State SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_ivr_bridge.c:981 sofia/internal/601@10.1.10.150:5062 CUSTOM SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:400 sofia/internal/601@10.1.10.150:5062 Standard SOFT_EXECUTE
2017-06-12 11:46:23.452235 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/601@10.1.10.150:5062) State SOFT_EXECUTE going to sleep
2017-06-12 11:46:23.472238 [DEBUG] switch_ivr_bridge.c:1496 (sofia/internal/601@10.1.10.150:5062) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
2017-06-12 11:46:23.472238 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 182)
2017-06-12 11:46:23.472238 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA
2017-06-12 11:46:23.472238 [DEBUG] switch_ivr_bridge.c:920 sofia/internal/601@10.1.10.150:5062 CUSTOM HOLD
2017-06-12 11:46:23.472238 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA going to sleep
2017-06-12 11:46:23.472238 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/601@10.1.10.150:5062) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-06-12 11:46:23.472238 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_EXCHANGE_MEDIA (Cur 4 Tot 182)
2017-06-12 11:46:23.472238 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/601@10.1.10.150:5062) State EXCHANGE_MEDIA
2017-06-12 11:46:23.472238 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2017-06-12 11:46:23.472238 [DEBUG] mod_callcenter.c:1842 Member "111" 111 is bridged to agent tester@pbx.domain.com
2017-06-12 11:46:23.472238 [DEBUG] mod_callcenter.c:1256 Updated tier: Agent tester@pbx.domain.com in Queue Payments@pbx.domain.com set state = Active Inbound
2017-06-12 11:46:23.472238 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = In a queue call
2017-06-12 11:46:23.492237 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [calling][0]
2017-06-12 11:46:23.492237 [DEBUG] sofia.c:7048 Channel sofia/internal/111@pbx.domain.com:5060 entering state [calling][0]
2017-06-12 11:46:23.492237 [DEBUG] sofia.c:7048 Channel sofia/internal/111@pbx.domain.com:5060 entering state [ready][200]
2017-06-12 11:46:23.492237 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20168 20169 IN IP4 10.1.10.65
s=SDP data
c=IN IP4 10.1.10.65
t=0 0
m=audio 12162 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:4754 sofia/internal/111@pbx.domain.com:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:46:23.492237 [DEBUG] sofia.c:8025 Processing updated SDP
2017-06-12 11:46:23.492237 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/111@pbx.domain.com:5060.
2017-06-12 11:46:23.652279 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [ready][200]
2017-06-12 11:46:23.652279 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20000 20001 IN IP4 10.1.10.150
s=SDP data
c=IN IP4 10.1.10.150
t=0 0
a=sendrecv
m=audio 11780 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:4754 sofia/internal/601@10.1.10.150:5062 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:46:23.652279 [DEBUG] sofia.c:8025 Processing updated SDP
2017-06-12 11:46:23.652279 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/601@10.1.10.150:5062.
2017-06-12 11:46:23.792240 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed.
2017-06-12 11:46:25.732253 [DEBUG] sofia.c:8508 Process REFER to [5505@63.78.119.44]
2017-06-12 11:46:25.732253 [DEBUG] sofia.c:8534 Replaces: [0_3321424007@10.1.10.65]
2017-06-12 11:46:25.732253 [NOTICE] sofia.c:8731 Attended Transfer [d60e4737-94ed-4341-a352-ac554deff4bb][b80d97e1-ca90-4cf4-a030-2c32baf23c18]
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:2017 (sofia/internal/8012790596@67.211.74.200) State Change CS_SOFT_EXECUTE -> CS_HIBERNATE
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:2019 (sofia/internal/601@10.1.10.150:5062) State Change CS_EXCHANGE_MEDIA -> CS_HIBERNATE
2017-06-12 11:46:25.732253 [DEBUG] sofia.c:8806 (sofia/internal/111@pbx.domain.com:5060) State Change CS_SOFT_EXECUTE -> CS_PARK
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/601@10.1.10.150:5062]
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/601@10.1.10.150:5062) State EXCHANGE_MEDIA going to sleep
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_HIBERNATE (Cur 4 Tot 182)
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/601@10.1.10.150:5062) State HIBERNATE
2017-06-12 11:46:25.732253 [DEBUG] mod_sofia.c:180 sofia/internal/601@10.1.10.150:5062 SOFIA HIBERNATE
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:971 (sofia/internal/601@10.1.10.150:5062) State Change CS_HIBERNATE -> CS_RESET
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:665 (sofia/internal/601@10.1.10.150:5062) State HIBERNATE going to sleep
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_RESET (Cur 4 Tot 182)
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/601@10.1.10.150:5062) State RESET
2017-06-12 11:46:25.732253 [DEBUG] mod_sofia.c:161 sofia/internal/601@10.1.10.150:5062 SOFIA RESET
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:956 sofia/internal/601@10.1.10.150:5062 CUSTOM RESET
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:188 sofia/internal/601@10.1.10.150:5062 Standard RESET
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/601@10.1.10.150:5062) State RESET going to sleep
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/601@10.1.10.150:5062 ending bridge by request from write function
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/111@pbx.domain.com:5060]
2017-06-12 11:46:25.732253 [NOTICE] switch_ivr_bridge.c:1751 Hangup sofia/internal/111@pbx.domain.com:5060 [CS_PARK] [NORMAL_CLEARING]
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/111@pbx.domain.com:5060) State SOFT_EXECUTE going to sleep
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_HANGUP (Cur 4 Tot 182)
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/111@pbx.domain.com:5060) Callstate Change ACTIVE -> HANGUP
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/111@pbx.domain.com:5060) State HANGUP
2017-06-12 11:46:25.732253 [DEBUG] mod_sofia.c:438 Channel sofia/internal/111@pbx.domain.com:5060 hanging up, cause: NORMAL_CLEARING
2017-06-12 11:46:25.732253 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/111@pbx.domain.com:5060
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:60 sofia/internal/111@pbx.domain.com:5060 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/111@pbx.domain.com:5060) State HANGUP going to sleep
2017-06-12 11:46:25.732253 [DEBUG] switch_ivr_play_say.c:1942 done playing file local_stream://default
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/111@pbx.domain.com:5060) State Change CS_HANGUP -> CS_REPORTING
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_REPORTING (Cur 4 Tot 182)
2017-06-12 11:46:25.732253 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/111@pbx.domain.com:5060) State REPORTING
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/8012790596@67.211.74.200]
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:174 sofia/internal/111@pbx.domain.com:5060 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/111@pbx.domain.com:5060) State REPORTING going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/111@pbx.domain.com:5060) State Change CS_REPORTING -> CS_DESTROY
2017-06-12 11:46:25.752254 [DEBUG] switch_core_session.c:1664 Session 180 (sofia/internal/111@pbx.domain.com:5060) Locked, Waiting on external entities
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/111@10.1.10.65:5060]
2017-06-12 11:46:25.752254 [DEBUG] switch_channel.c:2029 (sofia/internal/111@10.1.10.65:5060) Callstate Change HELD -> UNHELD
2017-06-12 11:46:25.752254 [NOTICE] switch_ivr_bridge.c:891 Hangup sofia/internal/111@10.1.10.65:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/111@10.1.10.65:5060) State EXCHANGE_MEDIA going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_HANGUP (Cur 4 Tot 182)
2017-06-12 11:46:25.752254 [DEBUG] sofia.c:1453 Channel is already hungup.
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/111@10.1.10.65:5060) Callstate Change UNHELD -> HANGUP
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/111@10.1.10.65:5060) State HANGUP
2017-06-12 11:46:25.752254 [DEBUG] mod_sofia.c:438 Channel sofia/internal/111@10.1.10.65:5060 hanging up, cause: NORMAL_CLEARING
2017-06-12 11:46:25.752254 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/111@10.1.10.65:5060
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:1699 sofia/internal/111@10.1.10.65:5060 skip receive message [UNBRIDGE] (channel is hungup already)
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:60 sofia/internal/111@10.1.10.65:5060 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:1764 (sofia/internal/8012790596@67.211.74.200) State Change CS_HIBERNATE -> CS_RESET
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/8012790596@67.211.74.200) State SOFT_EXECUTE going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/111@10.1.10.65:5060) State HANGUP going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_RESET (Cur 4 Tot 182)
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/111@10.1.10.65:5060) State Change CS_HANGUP -> CS_REPORTING
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/8012790596@67.211.74.200) State RESET
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_REPORTING (Cur 4 Tot 182)
2017-06-12 11:46:25.752254 [DEBUG] mod_sofia.c:161 sofia/internal/8012790596@67.211.74.200 SOFIA RESET
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:956 sofia/internal/8012790596@67.211.74.200 CUSTOM RESET
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:963 (sofia/internal/8012790596@67.211.74.200) State Change CS_RESET -> CS_SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:646 (sofia/internal/8012790596@67.211.74.200) State RESET going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_SOFT_EXECUTE (Cur 4 Tot 182)
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/8012790596@67.211.74.200) State SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:981 sofia/internal/8012790596@67.211.74.200 CUSTOM SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:1013 (sofia/internal/601@10.1.10.150:5062) State Change CS_RESET -> CS_SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_SOFT_EXECUTE (Cur 4 Tot 182)
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/111@10.1.10.65:5060) State REPORTING
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:174 sofia/internal/111@10.1.10.65:5060 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/111@10.1.10.65:5060) State REPORTING going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/601@10.1.10.150:5062) State SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] mod_sofia.c:637 SOFIA SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_ivr_bridge.c:981 sofia/internal/601@10.1.10.150:5062 CUSTOM SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:400 sofia/internal/601@10.1.10.150:5062 Standard SOFT_EXECUTE
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/601@10.1.10.150:5062) State SOFT_EXECUTE going to sleep
2017-06-12 11:46:25.752254 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/111@10.1.10.65:5060) State Change CS_REPORTING -> CS_DESTROY
2017-06-12 11:46:25.752254 [DEBUG] switch_core_session.c:1664 Session 178 (sofia/internal/111@10.1.10.65:5060) Locked, Waiting on external entities
2017-06-12 11:46:25.772240 [DEBUG] switch_ivr_bridge.c:1496 (sofia/internal/601@10.1.10.150:5062) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA
2017-06-12 11:46:25.772240 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 182)
2017-06-12 11:46:25.772240 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA
2017-06-12 11:46:25.772240 [DEBUG] switch_ivr_bridge.c:920 sofia/internal/601@10.1.10.150:5062 CUSTOM HOLD
2017-06-12 11:46:25.772240 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/601@10.1.10.150:5062) State CONSUME_MEDIA going to sleep
2017-06-12 11:46:25.772240 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/601@10.1.10.150:5062) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-06-12 11:46:25.772240 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_EXCHANGE_MEDIA (Cur 4 Tot 182)
2017-06-12 11:46:25.772240 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/601@10.1.10.150:5062) State EXCHANGE_MEDIA
2017-06-12 11:46:25.772240 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2017-06-12 11:46:25.772240 [NOTICE] switch_core_io.c:1202 Activating write resampler
2017-06-12 11:46:25.772240 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 160 bytes to accommodate 320->160
2017-06-12 11:46:25.792253 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [calling][0]
2017-06-12 11:46:25.812239 [NOTICE] switch_core_io.c:1202 Activating write resampler
2017-06-12 11:46:25.812239 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 640 bytes to accommodate 320->640
2017-06-12 11:46:25.832259 [DEBUG] mod_callcenter.c:1135 Updated Agent mJOHNSON@pbx.domain.com set state = Waiting
2017-06-12 11:46:25.832259 [NOTICE] switch_core_session.c:1682 Session 178 (sofia/internal/111@10.1.10.65:5060) Ended
2017-06-12 11:46:25.832259 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/111@10.1.10.65:5060 [CS_DESTROY]
2017-06-12 11:46:25.832259 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/111@10.1.10.65:5060) Running State Change CS_DESTROY (Cur 3 Tot 182)
2017-06-12 11:46:25.832259 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/111@10.1.10.65:5060) State DESTROY
2017-06-12 11:46:25.832259 [DEBUG] mod_sofia.c:343 sofia/internal/111@10.1.10.65:5060 SOFIA DESTROY
2017-06-12 11:46:25.832259 [DEBUG] switch_core_state_machine.c:181 sofia/internal/111@10.1.10.65:5060 Standard DESTROY
2017-06-12 11:46:25.832259 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/111@10.1.10.65:5060) State DESTROY going to sleep
2017-06-12 11:46:25.912250 [DEBUG] sofia.c:7048 Channel sofia/internal/601@10.1.10.150:5062 entering state [ready][200]
2017-06-12 11:46:25.912250 [DEBUG] sofia.c:7058 Remote SDP:
v=0
o=- 20000 20002 IN IP4 10.1.10.150
s=SDP data
c=IN IP4 10.1.10.150
t=0 0
a=sendrecv
m=audio 11780 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:4754 sofia/internal/601@10.1.10.150:5062 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-12 11:46:25.912250 [DEBUG] sofia.c:8025 Processing updated SDP
2017-06-12 11:46:25.912250 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/601@10.1.10.150:5062.
2017-06-12 11:47:50.012255 [DEBUG] switch_rtp.c:1460  [  zrtp cache]:   Storing ZRTP cache to </var/lib/freeswitch/db/zrtp.dat>...
2017-06-12 11:47:50.012255 [DEBUG] switch_rtp.c:1321 Saving ZRTP cache: OK
2017-06-12 11:48:03.812253 [NOTICE] sofia.c:1012 Hangup sofia/internal/601@10.1.10.150:5062 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2017-06-12 11:48:03.812253 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/601@10.1.10.150:5062]
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/601@10.1.10.150:5062) State EXCHANGE_MEDIA going to sleep
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_HANGUP (Cur 3 Tot 182)
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/601@10.1.10.150:5062) Callstate Change ACTIVE -> HANGUP
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/601@10.1.10.150:5062) State HANGUP
2017-06-12 11:48:03.812253 [DEBUG] mod_sofia.c:438 Channel sofia/internal/601@10.1.10.150:5062 hanging up, cause: NORMAL_CLEARING
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:60 sofia/internal/601@10.1.10.150:5062 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/601@10.1.10.150:5062) State HANGUP going to sleep
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/601@10.1.10.150:5062) State Change CS_HANGUP -> CS_REPORTING
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_REPORTING (Cur 3 Tot 182)
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/601@10.1.10.150:5062) State REPORTING
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:174 sofia/internal/601@10.1.10.150:5062 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/601@10.1.10.150:5062) State REPORTING going to sleep
2017-06-12 11:48:03.812253 [DEBUG] mod_callcenter.c:1135 Updated Agent tester@pbx.domain.com set state = Waiting
2017-06-12 11:48:03.812253 [NOTICE] switch_core_session.c:1682 Session 180 (sofia/internal/111@pbx.domain.com:5060) Ended
2017-06-12 11:48:03.812253 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/111@pbx.domain.com:5060 [CS_DESTROY]
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/601@10.1.10.150:5062) State Change CS_REPORTING -> CS_DESTROY
2017-06-12 11:48:03.812253 [DEBUG] switch_core_session.c:1664 Session 182 (sofia/internal/601@10.1.10.150:5062) Locked, Waiting on external entities
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/111@pbx.domain.com:5060) Running State Change CS_DESTROY (Cur 2 Tot 182)
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/111@pbx.domain.com:5060) State DESTROY
2017-06-12 11:48:03.812253 [DEBUG] mod_sofia.c:343 sofia/internal/111@pbx.domain.com:5060 SOFIA DESTROY
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:181 sofia/internal/111@pbx.domain.com:5060 Standard DESTROY
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/111@pbx.domain.com:5060) State DESTROY going to sleep
2017-06-12 11:48:03.812253 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/601@10.1.10.150:5062 ending bridge by request from write function
2017-06-12 11:48:03.812253 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/8012790596@67.211.74.200]
2017-06-12 11:48:03.812253 [NOTICE] switch_ivr_bridge.c:1751 Hangup sofia/internal/8012790596@67.211.74.200 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:656 (sofia/internal/8012790596@67.211.74.200) State SOFT_EXECUTE going to sleep
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_HANGUP (Cur 2 Tot 182)
2017-06-12 11:48:03.812253 [NOTICE] switch_core_session.c:1682 Session 182 (sofia/internal/601@10.1.10.150:5062) Ended
2017-06-12 11:48:03.812253 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/601@10.1.10.150:5062 [CS_DESTROY]
2017-06-12 11:48:03.812253 [DEBUG] switch_ivr_async.c:1316 Stop recording file /media/fusionpbx/pbx.domain.com/recordings/2017/Jun/12/d60e4737-94ed-4341-a352-ac554deff4bb.wav
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/601@10.1.10.150:5062) Running State Change CS_DESTROY (Cur 1 Tot 182)
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/601@10.1.10.150:5062) State DESTROY
2017-06-12 11:48:03.812253 [DEBUG] mod_sofia.c:343 sofia/internal/601@10.1.10.150:5062 SOFIA DESTROY
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:181 sofia/internal/601@10.1.10.150:5062 Standard DESTROY
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/601@10.1.10.150:5062) State DESTROY going to sleep
2017-06-12 11:48:03.812253 [DEBUG] switch_ivr_async.c:1380 Channel is hung up
2017-06-12 11:48:03.812253 [DEBUG] switch_core_media_bug.c:1124 Removing BUG from sofia/internal/8012790596@67.211.74.200
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/8012790596@67.211.74.200) Callstate Change ACTIVE -> HANGUP
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/8012790596@67.211.74.200) State HANGUP
2017-06-12 11:48:03.812253 [DEBUG] mod_sofia.c:432 sofia/internal/8012790596@67.211.74.200 Overriding SIP cause 480 with 200 from the other leg
2017-06-12 11:48:03.812253 [DEBUG] mod_sofia.c:438 Channel sofia/internal/8012790596@67.211.74.200 hanging up, cause: NORMAL_CLEARING
2017-06-12 11:48:03.812253 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/8012790596@67.211.74.200
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:60 sofia/internal/8012790596@67.211.74.200 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/8012790596@67.211.74.200) State HANGUP going to sleep
2017-06-12 11:48:03.812253 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/8012790596@67.211.74.200) State Change CS_HANGUP -> CS_REPORTING
2017-06-12 11:48:03.832255 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_REPORTING (Cur 1 Tot 182)
2017-06-12 11:48:03.832255 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/8012790596@67.211.74.200) State REPORTING
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:174 sofia/internal/8012790596@67.211.74.200 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/8012790596@67.211.74.200) State REPORTING going to sleep
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/8012790596@67.211.74.200) State Change CS_REPORTING -> CS_DESTROY
2017-06-12 11:48:03.852276 [DEBUG] switch_core_session.c:1664 Session 177 (sofia/internal/8012790596@67.211.74.200) Locked, Waiting on external entities
2017-06-12 11:48:03.852276 [NOTICE] switch_core_session.c:1682 Session 177 (sofia/internal/8012790596@67.211.74.200) Ended
2017-06-12 11:48:03.852276 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/8012790596@67.211.74.200 [CS_DESTROY]
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/8012790596@67.211.74.200) Running State Change CS_DESTROY (Cur 0 Tot 182)
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/8012790596@67.211.74.200) State DESTROY
2017-06-12 11:48:03.852276 [DEBUG] mod_sofia.c:343 sofia/internal/8012790596@67.211.74.200 SOFIA DESTROY
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:181 sofia/internal/8012790596@67.211.74.200 Standard DESTROY
2017-06-12 11:48:03.852276 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/8012790596@67.211.74.200) State DESTROY going to sleep
freeswitch@pbx.domain.com> /bye
root@pbx:/etc# /media/fusionpbx/pbx.domain.com/recordings/2017/Jun/12/
bash: /media/fusionpbx/pbx.domain.com/recordings/2017/Jun/12/: Is a directory
root@pbx:/etc# cd /media/fusionpbx/pbx.domain.com/recordings/2017/Jun/12/
root@pbx:/media/fusionpbx/pbx.domain.com/recordings/2017/Jun/12# ll
total 2176
-rw-rw---- 1 www-data www-data 2224474 Jun 12 11:49 d60e4737-94ed-4341-a352-ac554deff4bb.wav