2019-04-02 18:21:55.692810 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1003@riverwalk.cust.tellarc.com [27a10d0e-9622-4210-af84-ca802ece35a8] 2019-04-02 18:21:55.692810 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_NEW (Cur 5 Tot 31356) 2019-04-02 18:21:55.692810 [DEBUG] sofia.c:10092 sofia/internal/1003@riverwalk.cust.tellarc.com receiving invite from 96.65.187.108:8133 version: 1.8.3 -4-4d4c454d3e 64bit 2019-04-02 18:21:55.692810 [DEBUG] sofia.c:10263 IP 96.65.187.108 Rejected by acl "domains". Falling back to Digest auth. 2019-04-02 18:21:55.692810 [WARNING] sofia_reg.c:1796 SIP auth challenge (INVITE) on sofia profile 'internal' for [*97@riverwalk.cust.tellarc.com] from ip 96.65.187.108 2019-04-02 18:21:55.692810 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1003@riverwalk.cust.tellarc.com) State NEW 2019-04-02 18:21:55.692810 [DEBUG] sofia.c:2413 detaching session 27a10d0e-9622-4210-af84-ca802ece35a8 2019-04-02 18:21:55.852848 [DEBUG] sofia.c:2522 Re-attaching to session 27a10d0e-9622-4210-af84-ca802ece35a8 2019-04-02 18:21:55.852848 [DEBUG] sofia.c:10092 sofia/internal/1003@riverwalk.cust.tellarc.com receiving invite from 96.65.187.108:8133 version: 1.8.3 -4-4d4c454d3e 64bit 2019-04-02 18:21:55.852848 [DEBUG] sofia.c:10263 IP 96.65.187.108 Rejected by acl "domains". Falling back to Digest auth. 2019-04-02 18:21:55.872794 [DEBUG] sofia.c:11400 Setting NAT mode based on via received 2019-04-02 18:21:55.872794 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@riverwalk.cust.tellarc.com entering state [received][100] 2019-04-02 18:21:55.872794 [DEBUG] sofia.c:7301 Remote SDP: v=0 o=- 114909373 114909373 IN IP4 192.168.1.67 s=- c=IN IP4 192.168.1.67 t=0 0 m=audio 16468 RTP/AVP 0 2 8 9 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-32:2:8000:20:0:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729a:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729a:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-40:96:8000:20:0:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-40:96:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-24:97:8000:20:0:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-24:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-16:98:8000:20:0:1]/[opus:116:48000:20:0:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G726-16:98:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/1003@riverwalk.cust.tellarc.com PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2019-04-02 18:21:55.872794 [DEBUG] switch_core_codec.c:111 sofia/internal/1003@riverwalk.cust.tellarc.com Original read codec set to PCMU:0 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000 2019-04-02 18:21:55.872794 [DEBUG] switch_core_media.c:5795 sofia/internal/1003@riverwalk.cust.tellarc.com Set 2833 dtmf send payload to 101 recv payload to 101 2019-04-02 18:21:55.872794 [DEBUG] sofia.c:7716 (sofia/internal/1003@riverwalk.cust.tellarc.com) State Change CS_NEW -> CS_INIT 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_INIT (Cur 5 Tot 31356) 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@riverwalk.cust.tellarc.com) State INIT 2019-04-02 18:21:55.872794 [DEBUG] mod_sofia.c:93 sofia/internal/1003@riverwalk.cust.tellarc.com SOFIA INIT 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@riverwalk.cust.tellarc.com Standard INIT 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@riverwalk.cust.tellarc.com) State Change CS_INIT -> CS_ROUTING 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1003@riverwalk.cust.tellarc.com) State INIT going to sleep 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_ROUTING (Cur 5 Tot 31356) 2019-04-02 18:21:55.872794 [DEBUG] switch_channel.c:2249 (sofia/internal/1003@riverwalk.cust.tellarc.com) Callstate Change DOWN -> RINGING 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@riverwalk.cust.tellarc.com) State ROUTING 2019-04-02 18:21:55.872794 [DEBUG] mod_sofia.c:154 sofia/internal/1003@riverwalk.cust.tellarc.com SOFIA ROUTING 2019-04-02 18:21:55.872794 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1003@riverwalk.cust.tellarc.com Standard ROUTING 2019-04-02 18:21:55.872794 [INFO] mod_dialplan_xml.c:637 Processing Ilissa <1003>->*97 in context riverwalk.cust.tellarc.com Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->user_exists] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(user_exists=false) 2019-04-02 18:21:55.872794 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [user_exists]=[false] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->user_exists] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(user_exists=false) 2019-04-02 18:21:55.872794 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [user_exists]=[false] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->caller-details] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(caller_destination=${destination_number}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(caller_destination=*97) 2019-04-02 18:21:55.872794 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [caller_destination]=[*97] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(caller_id_name=${caller_id_name}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(caller_id_name=1003) 2019-04-02 18:21:55.872794 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [caller_id_name]=[1003] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(caller_id_number=${caller_id_number}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(caller_id_number=1003) 2019-04-02 18:21:55.872794 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [caller_id_number]=[1003] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->call-direction] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com ANTI-Action set(call_direction=local) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->variables] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [variables] () =~ // break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action export(origination_callee_id_name=${destination_number}) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(timezone=America/New_York) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(timezone=America/New_York) 2019-04-02 18:21:55.872794 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [timezone]=[America/New_York] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->is_local] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [is_local] () =~ // break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action lua(app.lua is_local) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->is_loopback] continue= Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->user_record] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_record] () =~ // break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(user_record=) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [user_record]=[UNDEF] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(from_user_exists=true) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [from_user_exists]=[true] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(from_user_record=) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [from_user_record]=[UNDEF] Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->redial] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [redial] destination_number(*97) =~ /^(redial|\*870)$/ break=on-true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [redial] () =~ // break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->speed_dial] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [speed_dial] destination_number(*97) =~ /^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->default_caller_id] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [default_caller_id] ${emergency_caller_id_number}(5616977712) =~ /^$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(5616977712) =~ /^$/ break=never Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->911-v1voip] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [911-v1voip] destination_number(*97) =~ /^(911)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->teli.911-global] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [teli.911-global] ${user_exists}(false) =~ /false/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [teli.911-global] destination_number(*97) =~ /^(911|933)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->ring group] continue= Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [ring group] destination_number(*97) =~ /^7501$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->sbc0.7d] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [sbc0.7d] destination_number(*97) =~ /^(\d{7})$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->sbc0.d4] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [sbc0.d4] destination_number(*97) =~ /^(1?411)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->fax] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [fax] destination_number(*97) =~ /^919191?(\d{10})$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->10-11-mix] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [10-11-mix] destination_number(*97) =~ /^\+?1?(\d{10})$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->agent_status] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [agent_status] destination_number(*97) =~ /^\*22$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->agent_status_id] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [agent_status_id] destination_number(*97) =~ /^\*23$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->group-intercept] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [group-intercept] destination_number(*97) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->page-extension] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [page-extension] destination_number(*97) =~ /^\*8(\d{2,7})$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->eavesdrop] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [eavesdrop] destination_number(*97) =~ /^\*33(\d{2,7})$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->call_privacy] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [call_privacy] destination_number(*97) =~ /^\*67(\d+)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->call_return] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [call_return] destination_number(*97) =~ /^\*69$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->intercept-ext] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [intercept-ext] destination_number(*97) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->intercept-ext-polycom] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [intercept-ext-polycom] destination_number(*97) =~ /^\*97(\d+)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->extension_queue] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [extension_queue] destination_number(*97) =~ /^\*800(.*)$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->Riverwalk-Main] continue=true Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [Riverwalk-Main] destination_number(*97) =~ /^7601$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->dx] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [dx] destination_number(*97) =~ /^dx$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->att_xfer] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [att_xfer] destination_number(*97) =~ /^att_xfer$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->extension-to-voicemail] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [extension-to-voicemail] ${user_exists}(false) =~ /^true$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->send_to_voicemail] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [send_to_voicemail] destination_number(*97) =~ /^\*99(\d{2,7})$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->Riverwalk-fax] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [Riverwalk-fax] destination_number(*97) =~ /^7901$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->extension-to-voicemail] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [extension-to-voicemail] username(1003) =~ /^1003$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [extension-to-voicemail] destination_number(*97) =~ /^1003$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->xfer_vm] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [xfer_vm] destination_number(*97) =~ /^xfer_vm$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->vmain] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (FAIL) [vmain] destination_number(*97) =~ /^vmain$|^\*4000$|^\*98$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com parsing [riverwalk.cust.tellarc.com->vmain_user] continue=false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Regex (PASS) [vmain_user] destination_number(*97) =~ /^\*97$/ break=on-false Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action answer() Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action sleep(1000) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(voicemail_action=check) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(voicemail_id=${caller_id_number}) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action set(voicemail_profile=default) Dialplan: sofia/internal/1003@riverwalk.cust.tellarc.com Action lua(app.lua voicemail) 2019-04-02 18:21:55.912891 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1003@riverwalk.cust.tellarc.com) State Change CS_ROUTING -> CS_EXECUTE 2019-04-02 18:21:55.912891 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1003@riverwalk.cust.tellarc.com) State ROUTING going to sleep 2019-04-02 18:21:55.912891 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_EXECUTE (Cur 5 Tot 31356) 2019-04-02 18:21:55.912891 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1003@riverwalk.cust.tellarc.com) State EXECUTE 2019-04-02 18:21:55.912891 [DEBUG] mod_sofia.c:209 sofia/internal/1003@riverwalk.cust.tellarc.com SOFIA EXECUTE 2019-04-02 18:21:55.912891 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1003@riverwalk.cust.tellarc.com Standard EXECUTE EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(call_direction=local) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [call_direction]=[local] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com export(origination_callee_id_name=*97) 2019-04-02 18:21:55.912891 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[*97] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(RFC2822_DATE=Tue, 02 Apr 2019 18:21:55 -0400) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [RFC2822_DATE]=[Tue, 02 Apr 2019 18:21:55 -0400] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com lua(app.lua is_local) EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(caller_id_name=Riverwalk) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [caller_id_name]=[Riverwalk] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(effective_caller_id_name=Riverwalk) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [effective_caller_id_name]=[Riverwalk] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(caller_id_number=5616977712) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [caller_id_number]=[5616977712] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(effective_caller_id_number=5616977712) 2019-04-02 18:21:55.912891 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [effective_caller_id_number]=[5616977712] 2019-04-02 18:21:55.932800 [DEBUG] switch_cpp.cpp:1187 sofia/internal/1003@riverwalk.cust.tellarc.com destroy/unlink session from object EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com hash(insert/riverwalk.cust.tellarc.com-last_dial/5616977712/*97) EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com answer() 2019-04-02 18:21:55.932800 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/1003@riverwalk.cust.tellarc.com] 162.208.16.4 port 31794 -> 192.168.1.67 port 16468 codec: 0 ms: 20 2019-04-02 18:21:55.932800 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms 2019-04-02 18:21:55.932800 [DEBUG] switch_core_media.c:8815 sofia/internal/1003@riverwalk.cust.tellarc.com Set 2833 dtmf send payload to 101 2019-04-02 18:21:55.932800 [DEBUG] switch_core_media.c:8822 sofia/internal/1003@riverwalk.cust.tellarc.com Set 2833 dtmf receive payload to 101 2019-04-02 18:21:55.932800 [DEBUG] switch_core_media.c:8845 sofia/internal/1003@riverwalk.cust.tellarc.com Set rtp dtmf delay to 40 2019-04-02 18:21:55.932800 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1003@riverwalk.cust.tellarc.com: v=0 o=FreeSWITCH 1554211921 1554211922 IN IP4 162.208.16.4 s=FreeSWITCH c=IN IP4 162.208.16.4 t=0 0 m=audio 31794 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2019-04-02 18:21:55.932800 [NOTICE] mod_dptools.c:1360 Channel [sofia/internal/1003@riverwalk.cust.tellarc.com] has been answered 2019-04-02 18:21:55.932800 [DEBUG] switch_channel.c:3781 (sofia/internal/1003@riverwalk.cust.tellarc.com) Callstate Change RINGING -> ACTIVE 2019-04-02 18:21:55.932800 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@riverwalk.cust.tellarc.com entering state [completed][200] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com sleep(1000) 2019-04-02 18:21:56.072822 [DEBUG] sofia.c:7291 Channel sofia/internal/1003@riverwalk.cust.tellarc.com entering state [ready][200] 2019-04-02 18:21:56.252825 [INFO] switch_rtp.c:7510 Auto Changing audio port from 192.168.1.67:16468 to 96.65.187.108:9270 EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(voicemail_action=check) 2019-04-02 18:21:56.932810 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [voicemail_action]=[check] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(voicemail_id=5616977712) 2019-04-02 18:21:56.932810 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [voicemail_id]=[5616977712] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com set(voicemail_profile=default) 2019-04-02 18:21:56.932810 [DEBUG] mod_dptools.c:1598 SET sofia/internal/1003@riverwalk.cust.tellarc.com [voicemail_profile]=[default] EXECUTE sofia/internal/1003@riverwalk.cust.tellarc.com lua(app.lua voicemail) 2019-04-02 18:21:56.932810 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('playback_terminators', '#') 2019-04-02 18:21:56.952812 [DEBUG] switch_cpp.cpp:731 CoreSession::hangup 2019-04-02 18:21:56.952812 [NOTICE] switch_cpp.cpp:733 Hangup sofia/internal/1003@riverwalk.cust.tellarc.com [CS_EXECUTE] [NORMAL_CLEARING] 2019-04-02 18:21:56.952812 [DEBUG] switch_cpp.cpp:1187 sofia/internal/1003@riverwalk.cust.tellarc.com destroy/unlink session from object 2019-04-02 18:21:56.952812 [DEBUG] switch_core_session.c:2887 sofia/internal/1003@riverwalk.cust.tellarc.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1003@riverwalk.cust.tellarc.com) State EXECUTE going to sleep 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_HANGUP (Cur 5 Tot 31356) 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/1003@riverwalk.cust.tellarc.com) Callstate Change ACTIVE -> HANGUP 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1003@riverwalk.cust.tellarc.com) State HANGUP 2019-04-02 18:21:56.952812 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1003@riverwalk.cust.tellarc.com hanging up, cause: NORMAL_CLEARING 2019-04-02 18:21:56.952812 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/1003@riverwalk.cust.tellarc.com 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1003@riverwalk.cust.tellarc.com Standard HANGUP, cause: NORMAL_CLEARING 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1003@riverwalk.cust.tellarc.com) State HANGUP going to sleep 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1003@riverwalk.cust.tellarc.com) State Change CS_HANGUP -> CS_REPORTING 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_REPORTING (Cur 5 Tot 31356) 2019-04-02 18:21:56.952812 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1003@riverwalk.cust.tellarc.com) State REPORTING 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1003@riverwalk.cust.tellarc.com Standard REPORTING, cause: NORMAL_CLEARING 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1003@riverwalk.cust.tellarc.com) State REPORTING going to sleep 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1003@riverwalk.cust.tellarc.com) State Change CS_REPORTING -> CS_DESTROY 2019-04-02 18:21:57.012818 [DEBUG] switch_core_session.c:1715 Session 31356 (sofia/internal/1003@riverwalk.cust.tellarc.com) Locked, Waiting on external entities 2019-04-02 18:21:57.012818 [NOTICE] switch_core_session.c:1733 Session 31356 (sofia/internal/1003@riverwalk.cust.tellarc.com) Ended 2019-04-02 18:21:57.012818 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/1003@riverwalk.cust.tellarc.com [CS_DESTROY] 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/1003@riverwalk.cust.tellarc.com) Running State Change CS_DESTROY (Cur 4 Tot 31356) 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1003@riverwalk.cust.tellarc.com) State DESTROY 2019-04-02 18:21:57.012818 [DEBUG] mod_sofia.c:354 sofia/internal/1003@riverwalk.cust.tellarc.com SOFIA DESTROY 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1003@riverwalk.cust.tellarc.com Standard DESTROY 2019-04-02 18:21:57.012818 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1003@riverwalk.cust.tellarc.com) State DESTROY going to sleep