Receive SIP Event [nua_r_invite] Status 503 Service Unavailable [uni2]
166 views
Skip to first unread message
Nguyễn Võ Duy Phùng
Jul 11, 2023, 12:34:28 AM7/11/23
to UniMRCP
Have a good time for everyone.
I just paid for the Product License named "Deepgram Speech Recognition" and am I in the process of using it. I have trouble trunking between Freeswitch and Deepgram. I have set up and configured parameters on both Freeswitch and Deepgram by performing step-by-step in docs.unispeech.io,
setting Public IP in the file unimrcp-v2-profile.xml,
bypass firewall also disable SELinux on and then testing.
But I cannot make any calls normally and get an error "mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 503 Service Unavailable" [uni2] when making a call.
I have researched some groups, and forums related to my issue and followed it but it was not worked. I will attach pieces of information, such as logs, and capture calls about my issue.
I would highly appreciate any information about my order. Many thanks for your support.
[This app Best viewed at 160x60 or more..]
+OK log level [7]
freeswitch@fscaching>
freeswitch@fscaching>
freeswitch@fscaching>
freeswitch@fscaching>
2023-07-11 10:08:15.093922 [WARNING] sofia_reg.c:1795 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1...@unimrcp.tel4vn .com] from ip 113.161.95.53
2023-07-11 10:08:18.673965 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1...@unimrcp.tel4vn.com [5a3bd400-a860-4e8a-8a5e-20 4718ac40bd]
2023-07-11 10:08:18.673965 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_NEW (Cur 1 Tot 10)
2023-07-11 10:08:18.673965 [INFO] sofia.c:10362 sofia/internal/1...@unimrcp.tel4vn.com receiving invite from 113.161.95.53:58527 version : 1.10.6-release git 1ff9d0a 2021-03-25 13:16:09Z 64bit call-id: 51e9e47a22274dfe9254b66827033418
2023-07-11 10:08:18.673965 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 113.161.95.53:0.
2023-07-11 10:08:18.733896 [WARNING] sofia_reg.c:1795 SIP auth challenge (INVITE) on sofia profile 'internal' for [44...@unimrcp.tel4vn. com] from ip 113.161.95.53
2023-07-11 10:08:18.733896 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1...@unimrcp.tel4vn.com) State NEW
2023-07-11 10:08:18.733896 [DEBUG] sofia.c:2447 detaching session 5a3bd400-a860-4e8a-8a5e-204718ac40bd
2023-07-11 10:08:18.733896 [DEBUG] sofia.c:2562 Re-attaching to session 5a3bd400-a860-4e8a-8a5e-204718ac40bd
2023-07-11 10:08:18.753930 [INFO] sofia.c:10362 sofia/internal/1...@unimrcp.tel4vn.com receiving invite from 113.161.95.53:58527 version : 1.10.6-release git 1ff9d0a 2021-03-25 13:16:09Z 64bit call-id: 51e9e47a22274dfe9254b66827033418
2023-07-11 10:08:18.753930 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 113.161.95.53:0.
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:11564 Setting NAT mode based on via received
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [received][100]
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:7416 Remote SDP:
v=0
o=- 3898058899 3898058899 IN IP4 192.168.2.34
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 8 0 101
c=IN IP4 192.168.2.34
b=TIAS:64000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:4001 IN IP4 192.168.2.34
a=ssrc:1868191256 cname:1610142c05fc7c13
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5517 Set telephone-event payload to 101@8000
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:3847 Set Codec sofia/internal/1...@unimrcp.tel4vn.com PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2023-07-11 10:08:18.998734 [DEBUG] switch_core_codec.c:111 sofia/internal/1...@unimrcp.tel4vn.com Original read codec set to PCMA:8
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5860 Set telephone-event payload to 101@8000
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5918 sofia/internal/1...@unimrcp.tel4vn.com Set 2833 dtmf send payload to 101 rec v payload to 101
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:7840 (sofia/internal/1...@unimrcp.tel4vn.com) State Change CS_NEW -> CS_INIT
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_INIT (Cur 1 Tot 10)
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1...@unimrcp.tel4vn.com) State INIT
2023-07-11 10:08:18.998734 [DEBUG] mod_sofia.c:93 sofia/internal/1...@unimrcp.tel4vn.com SOFIA INIT
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1...@unimrcp.tel4vn.com Standard INIT
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1...@unimrcp.tel4vn.com) State Change CS_INIT -> CS_RO UTING
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1...@unimrcp.tel4vn.com) State INIT going to sleep
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_ROUT ING (Cur 1 Tot 10)
2023-07-11 10:08:18.998734 [DEBUG] switch_channel.c:2332 (sofia/internal/1...@unimrcp.tel4vn.com) Callstate Change DOWN -> RINGING
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1...@unimrcp.tel4vn.com) State ROUTING
2023-07-11 10:08:18.998734 [DEBUG] mod_sofia.c:154 sofia/internal/1...@unimrcp.tel4vn.com SOFIA ROUTING
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1...@unimrcp.tel4vn.com Standard ROUTING
2023-07-11 10:08:18.998734 [INFO] mod_dialplan_xml.c:637 Processing 101 <101>->4455 in context unimrcp.tel4vn.com
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->user_exists] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(user_exists=false)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [user_exists]=[false]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->caller-details] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(caller_destination=4455)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [caller_destination]=[4455]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(caller_id_name=101)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [caller_id_name]=[101]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->call_block] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [call_block] ${call_direction}() =~ /^inbound$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->call-direction] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break =never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com export(call_direction=local)
2023-07-11 10:08:19.073891 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->variables] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->user_record] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(from_user_exists=true)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [from_user_exists]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_session=true)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_session]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_reco rd}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(from_user_record=all)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [from_user_record]=[all]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_session=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_session]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strft ime(%b)}/${strftime(%d)}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_path=/usr/local/freeswitch/recordings/unimrcp.tel4vn.com/archive/202 3/Jul/11)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_path]=[/usr/local/freeswitch/re cordings/unimrcp.tel4vn.com/archive/2023/Jul/11]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_name=${uuid}.${record_ext}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_name=5a3bd400-a860-4e8a-8a5e-204718ac40bd.mp3)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_name]=[5a3bd400-a860-4e8a-8a5e- 204718ac40bd.mp3]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(recording_follow_transfer=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(recording_follow_transfer=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [recording_follow_transfer]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_append=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_append=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_append]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_in_progress=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_in_progress=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_in_progress]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(${uuid_record ${uuid} start ${record_path}/${record_name}})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->click_to_call] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [click_to_call] ${click_to_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->redial] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [redial] destination_number(4455) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->speed_dial] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [speed_dial] destination_number(4455) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->default_caller_id] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(emergency_caller_id_name=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(emergency_caller_id_number=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(outbound_caller_id_name=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [outbound_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(outbound_caller_id_number=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [outbound_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->blacklist_check_outbound] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [blacklist_check_outbound] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(blacklist_result=${blacklist(check inbound_blocked ${caller_id_number})}) IN LINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(blacklist_result=false)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [blacklist_result]=[false]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [blacklist_check_outbound] ${blacklist_result}(false) =~ /^true$/ break=al ways
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->UAT.d1011] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [UAT.d1011] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [UAT.d1011] destination_number(4455) =~ /^(\d{10,11})$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->blacklist_check_inbound] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [blacklist_check_inbound] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(blacklist_result=${blacklist(check inbound_blocked ${caller_id_number})}) IN LINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(blacklist_result=false)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [blacklist_result]=[false]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [blacklist_check_inbound] ${blacklist_result}(false) =~ /^true$/ break=alw ays
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->agent_status] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [agent_status] destination_number(4455) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->unimrcpSTTDeepgram] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [unimrcpSTTDeepgram] destination_number(4455) =~ /^4455$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action lua(asr_tts_google.lua)
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1...@unimrcp.tel4vn.com) State Change CS_ROUTING -> C S_EXECUTE
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1...@unimrcp.tel4vn.com) State ROUTING going to sleep
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_EXEC UTE (Cur 1 Tot 10)
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1...@unimrcp.tel4vn.com) State EXECUTE
2023-07-11 10:08:19.093900 [DEBUG] mod_sofia.c:209 sofia/internal/1...@unimrcp.tel4vn.com SOFIA EXECUTE
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1...@unimrcp.tel4vn.com Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(caller_id_number=101)
2023-07-11 10:08:19.113902 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [caller_id_number]=[101]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com export(origination_callee_id_name=4455)
2023-07-11 10:08:19.113902 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[4455]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(RFC2822_DATE=Tue, 11 Jul 2023 10:08:19 +0700)
2023-07-11 10:08:19.113902 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [RFC2822_DATE]=[Tue, 11 Jul 2023 10:08: 19 +0700]
2023-07-11 10:08:19.113902 [INFO] switch_ivr_async.c:2855 Sending early media
2023-07-11 10:08:19.133953 [DEBUG] switch_core_media.c:8675 AUDIO RTP [sofia/internal/1...@unimrcp.tel4vn.com] 10.127.17.16 port 30770 - > 192.168.2.34 port 4000 codec: 8 ms: 20
2023-07-11 10:08:19.153928 [DEBUG] switch_rtp.c:4478 Starting timer [soft] 160 bytes per 20ms
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:8897 Activating RTCP PORT 4001
2023-07-11 10:08:19.153928 [DEBUG] switch_rtp.c:4876 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 4001
2023-07-11 10:08:19.153928 [DEBUG] switch_rtp.c:2638 Setting RTCP remote addr to 192.168.2.34:4001 2
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:8989 sofia/internal/1...@unimrcp.tel4vn.com Set 2833 dtmf send payload to 101
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:8996 sofia/internal/1...@unimrcp.tel4vn.com Set 2833 dtmf receive payload to 101
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:9019 sofia/internal/1...@unimrcp.tel4vn.com Set rtp dtmf delay to 40
2023-07-11 10:08:19.153928 [DEBUG] mod_sofia.c:2593 Ring SDP:
v=0
o=FreeSWITCH 1689014129 1689014130 IN IP4 113.164.246.16
s=FreeSWITCH
c=IN IP4 113.164.246.16
t=0 0
m=audio 30770 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=rtcp:30771 IN IP4 113.164.246.16
2023-07-11 10:08:19.153928 [NOTICE] mod_sofia.c:2596 Pre-Answer sofia/internal/1...@unimrcp.tel4vn.com!
2023-07-11 10:08:19.153928 [DEBUG] switch_channel.c:3565 (sofia/internal/1...@unimrcp.tel4vn.com) Callstate Change RINGING -> EARLY
2023-07-11 10:08:19.273887 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [early][183]
2023-07-11 10:08:19.293938 [DEBUG] switch_ivr_async.c:1427 Record session sample rate: 8000 -> 8000
2023-07-11 10:08:19.293938 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/internal/1...@unimrcp.tel4vn.com
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(+OK Success
)
2023-07-11 10:08:19.293938 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [+OK Success
]=[UNDEF]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com hash(insert/unimrcp.tel4vn.com-last_dial/101/4455)
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com lua(asr_tts_google.lua)
2023-07-11 10:08:19.373945 [DEBUG] switch_core_media.c:8657 Audio params are unchanged for sofia/internal/1...@unimrcp.tel4vn.com.
2023-07-11 10:08:19.373945 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/1...@unimrcp.tel4vn.com:
v=0
o=FreeSWITCH 1689014129 1689014131 IN IP4 113.164.246.16
s=FreeSWITCH
c=IN IP4 113.164.246.16
t=0 0
m=audio 30770 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=rtcp:30771 IN IP4 113.164.246.16
2023-07-11 10:08:19.373945 [NOTICE] switch_cpp.cpp:703 Channel [sofia/internal/1...@unimrcp.tel4vn.com] has been answered
2023-07-11 10:08:19.373945 [DEBUG] switch_channel.c:3865 (sofia/internal/1...@unimrcp.tel4vn.com) Callstate Change EARLY -> ACTIVE
2023-07-11 10:08:19.373945 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [completed][200]
2023-07-11 10:08:19.373945 [INFO] switch_rtp.c:7170 Auto Changing audio RTCP port from 192.168.2.34:4001 to 113.161.95.53:41122
2023-07-11 10:08:19.373945 [DEBUG] switch_rtp.c:2638 Setting RTCP remote addr to 113.161.95.53:41122 2
2023-07-11 10:08:19.373945 [DEBUG] switch_ivr_async.c:1717 No silence detection configured; assuming start of speech
2023-07-11 10:08:19.413908 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMA:8
2023-07-11 10:08:19.433991 [DEBUG] switch_rtp.c:1923 rtcp_stats_init: audio ssrc[1868191256] base_seq[24477]
2023-07-11 10:08:19.593948 [INFO] switch_rtp.c:7753 Auto Changing audio port from 192.168.2.34:4000 to 113.161.95.53:41121
2023-07-11 10:08:19.693916 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [ready][200]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com playback(/usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-welcome_to_free switch.wav)
2023-07-11 10:08:20.393945 [DEBUG] switch_ivr_play_say.c:1486 Codec Activated L16@8000hz 1 channels 20ms
2023-07-11 10:08:21.953923 [INFO] mod_shout.c:332 LAME 3.100 64bits (http://lame.sf.net)
2023-07-11 10:08:21.953923 [INFO] mod_shout.c:332 polyphase lowpass filter disabled
2023-07-11 10:08:23.013952 [DEBUG] switch_ivr_play_say.c:1931 done playing file /usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr- welcome_to_freeswitch.wav
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com play_and_detect_speech(/usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-p lease_enter_the_number_where_we_can_reach_you.wav detect:unimrcp:uni2 {start-input-timers=false,input-timeout=70000,recognition-timeout =70000}builtin:speech/transcribe?deepgram.model=phonecall;speech-start-timeout=100)
2023-07-11 10:08:24.573904 [INFO] mod_unimrcp.c:3128 asr_handle: name = unimrcp, codec = (null), rate = 8000, grammar = (null), param = uni2
2023-07-11 10:08:24.573904 [INFO] mod_unimrcp.c:3130 codec = L16, rate = 8000, dest = (null)
2023-07-11 10:08:24.573904 [DEBUG] mod_unimrcp.c:684 (ASR-7) audio queue created
2023-07-11 10:08:24.573904 [NOTICE] mrcp_application.c:96 (ASR-7) Create MRCP Handle 0x7f46c0122480 [uni2]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:133 (ASR-7) Create Channel ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46c00c93f0;4;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46c00c93f0;4;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:387 (ASR-7) Receive App Request ASR-7 <new> [2]
2023-07-11 10:08:24.573904 [INFO] mrcp_client.c:700 (ASR-7) Add MRCP Handle ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:1283 (ASR-7) Dispatch App Request ASR-7 <new> [2]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f46780181e0;1;0]
2023-07-11 10:08:24.573904 [NOTICE] mrcp_client_session.c:719 (ASR-7) Add Control Channel ASR-7 <new@speechrecog>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:745 (ASR-7) Add Media Termination ASR-7 <new@media-tm>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:777 (ASR-7) Add Media Termination ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f4678004fe0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f46780181e0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46740019a0;2;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46740019a0;2;0]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:294 (ASR-7) Control Channel Added ASR-7 <new@speechrecog>
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f4678004fe0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] mpf_context.c:182 () Add Media Context ASR-7
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46640062f0;3;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46640062f0;3;0]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:944 (ASR-7) Media Termination Added ASR-7 <new@media-tm>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:944 (ASR-7) Media Termination Added ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:411 (ASR-7) Send Offer ASR-7 <new> [c:1 a:1 v:0] to 42.96.44.195:8060
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:354 (ASR-7) Local SDP ASR-7 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 127.0.1.1
s=-
c=IN IP4 127.0.1.1
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4014 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=mid:1
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [uni2]
2023-07-11 10:08:24.573904 [NOTICE] mrcp_sofiasip_client_agent.c:547 (ASR-7) SIP Call State ASR-7 [calling]
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 503 Service Unavailable [ uni2]
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 503 Service Unavailable [u ni2]
2023-07-11 10:08:24.573904 [NOTICE] mrcp_sofiasip_client_agent.c:547 (ASR-7) SIP Call State ASR-7 [terminated]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f4654022f80;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f4654022f80;1;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:151 (ASR-7) Receive Answer ASR-7 <new> [c:0 a:0 v:0] Status 503
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:455 (ASR-7) Raise App Response ASR-7 <new> [2] FAILURE [2]
2023-07-11 10:08:24.573904 [ERR] mod_unimrcp.c:1914 (ASR-7) RECOGNIZER channel error!
2023-07-11 10:08:24.573904 [DEBUG] mod_unimrcp.c:1578 (ASR-7) CLOSED ==> ERROR
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] mod_unimrcp.c:1062 (ASR-7) Terminating MRCP session
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46c0081f10;4;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46c0081f10;4;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:387 (ASR-7) Receive App Request ASR-7 <new> [1]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:1283 (ASR-7) Dispatch App Request ASR-7 <new> [1]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:833 (ASR-7) Terminate Session ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:854 (ASR-7) Remove Control Channel ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f46780140e0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:864 (ASR-7) Subtract Media Termination ASR-7 <new@media-tm>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:885 (ASR-7) Subtract Media Termination ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f46640062f0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46740010a0;1;1]
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46740010a0;1;1]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f46780140e0;1;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:209 (ASR-7) Session Terminated ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f4674001a20;2;2]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f4674001a20;2;2]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:331 (ASR-7) Control Channel Removed ASR-7 <new@speechrecog>
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.593914 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f46640062f0;1;0]
2023-07-11 10:08:24.593914 [DEBUG] mpf_context.c:238 () Remove Media Context ASR-7
2023-07-11 10:08:24.593914 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f4678004fe0;3;0]
2023-07-11 10:08:24.593914 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f4678004fe0;3;0]
2023-07-11 10:08:24.593914 [DEBUG] mrcp_client_session.c:1014 (ASR-7) Media Termination Subtracted ASR-7 <new@media-tm>
2023-07-11 10:08:24.593914 [DEBUG] mrcp_client_session.c:1014 (ASR-7) Media Termination Subtracted ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.593914 [INFO] mrcp_client.c:710 (ASR-7) Remove MRCP Handle ASR-7 <new>
2023-07-11 10:08:24.593914 [INFO] mrcp_client_session.c:455 (ASR-7) Raise App Response ASR-7 <new> [1] SUCCESS [0]
2023-07-11 10:08:24.593914 [DEBUG] mod_unimrcp.c:1829 (ASR-7) Destroying MRCP session
2023-07-11 10:08:24.593914 [NOTICE] mrcp_application.c:182 (ASR-7) Destroy MRCP Handle ASR-7
2023-07-11 10:08:24.593914 [DEBUG] mod_unimrcp.c:1578 (ASR-7) ERROR ==> CLOSED
2023-07-11 10:08:24.593914 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
+OK log level [7]
freeswitch@fscaching>
freeswitch@fscaching>
freeswitch@fscaching>
freeswitch@fscaching>
2023-07-11 10:08:15.093922 [WARNING] sofia_reg.c:1795 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1...@unimrcp.tel4vn .com] from ip 113.161.95.53
2023-07-11 10:08:18.673965 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1...@unimrcp.tel4vn.com [5a3bd400-a860-4e8a-8a5e-20 4718ac40bd]
2023-07-11 10:08:18.673965 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_NEW (Cur 1 Tot 10)
2023-07-11 10:08:18.673965 [INFO] sofia.c:10362 sofia/internal/1...@unimrcp.tel4vn.com receiving invite from 113.161.95.53:58527 version : 1.10.6-release git 1ff9d0a 2021-03-25 13:16:09Z 64bit call-id: 51e9e47a22274dfe9254b66827033418
2023-07-11 10:08:18.673965 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 113.161.95.53:0.
2023-07-11 10:08:18.733896 [WARNING] sofia_reg.c:1795 SIP auth challenge (INVITE) on sofia profile 'internal' for [44...@unimrcp.tel4vn. com] from ip 113.161.95.53
2023-07-11 10:08:18.733896 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1...@unimrcp.tel4vn.com) State NEW
2023-07-11 10:08:18.733896 [DEBUG] sofia.c:2447 detaching session 5a3bd400-a860-4e8a-8a5e-204718ac40bd
2023-07-11 10:08:18.733896 [DEBUG] sofia.c:2562 Re-attaching to session 5a3bd400-a860-4e8a-8a5e-204718ac40bd
2023-07-11 10:08:18.753930 [INFO] sofia.c:10362 sofia/internal/1...@unimrcp.tel4vn.com receiving invite from 113.161.95.53:58527 version : 1.10.6-release git 1ff9d0a 2021-03-25 13:16:09Z 64bit call-id: 51e9e47a22274dfe9254b66827033418
2023-07-11 10:08:18.753930 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 113.161.95.53:0.
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:11564 Setting NAT mode based on via received
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [received][100]
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:7416 Remote SDP:
v=0
o=- 3898058899 3898058899 IN IP4 192.168.2.34
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 8 0 101
c=IN IP4 192.168.2.34
b=TIAS:64000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:4001 IN IP4 192.168.2.34
a=ssrc:1868191256 cname:1610142c05fc7c13
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5517 Set telephone-event payload to 101@8000
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:3847 Set Codec sofia/internal/1...@unimrcp.tel4vn.com PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2023-07-11 10:08:18.998734 [DEBUG] switch_core_codec.c:111 sofia/internal/1...@unimrcp.tel4vn.com Original read codec set to PCMA:8
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5860 Set telephone-event payload to 101@8000
2023-07-11 10:08:18.998734 [DEBUG] switch_core_media.c:5918 sofia/internal/1...@unimrcp.tel4vn.com Set 2833 dtmf send payload to 101 rec v payload to 101
2023-07-11 10:08:18.998734 [DEBUG] sofia.c:7840 (sofia/internal/1...@unimrcp.tel4vn.com) State Change CS_NEW -> CS_INIT
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_INIT (Cur 1 Tot 10)
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1...@unimrcp.tel4vn.com) State INIT
2023-07-11 10:08:18.998734 [DEBUG] mod_sofia.c:93 sofia/internal/1...@unimrcp.tel4vn.com SOFIA INIT
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1...@unimrcp.tel4vn.com Standard INIT
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1...@unimrcp.tel4vn.com) State Change CS_INIT -> CS_RO UTING
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1...@unimrcp.tel4vn.com) State INIT going to sleep
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_ROUT ING (Cur 1 Tot 10)
2023-07-11 10:08:18.998734 [DEBUG] switch_channel.c:2332 (sofia/internal/1...@unimrcp.tel4vn.com) Callstate Change DOWN -> RINGING
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1...@unimrcp.tel4vn.com) State ROUTING
2023-07-11 10:08:18.998734 [DEBUG] mod_sofia.c:154 sofia/internal/1...@unimrcp.tel4vn.com SOFIA ROUTING
2023-07-11 10:08:18.998734 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1...@unimrcp.tel4vn.com Standard ROUTING
2023-07-11 10:08:18.998734 [INFO] mod_dialplan_xml.c:637 Processing 101 <101>->4455 in context unimrcp.tel4vn.com
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->user_exists] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(user_exists=false)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [user_exists]=[false]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->caller-details] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(caller_destination=4455)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [caller_destination]=[4455]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(caller_id_name=101)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [caller_id_name]=[101]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->call_block] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [call_block] ${call_direction}() =~ /^inbound$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->call-direction] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break =never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com export(call_direction=local)
2023-07-11 10:08:19.073891 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->variables] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->user_record] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(from_user_exists=true)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [from_user_exists]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_session=true)
2023-07-11 10:08:19.073891 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_session]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_reco rd}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(from_user_record=all)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [from_user_record]=[all]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_session=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_session]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strft ime(%b)}/${strftime(%d)}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_path=/usr/local/freeswitch/recordings/unimrcp.tel4vn.com/archive/202 3/Jul/11)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_path]=[/usr/local/freeswitch/re cordings/unimrcp.tel4vn.com/archive/2023/Jul/11]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_name=${uuid}.${record_ext}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_name=5a3bd400-a860-4e8a-8a5e-204718ac40bd.mp3)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_name]=[5a3bd400-a860-4e8a-8a5e- 204718ac40bd.mp3]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(recording_follow_transfer=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(recording_follow_transfer=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [recording_follow_transfer]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_append=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_append=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_append]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(record_in_progress=true) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(record_in_progress=true)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [record_in_progress]=[true]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(${uuid_record ${uuid} start ${record_path}/${record_name}})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->click_to_call] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [click_to_call] ${click_to_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->redial] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [redial] destination_number(4455) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->speed_dial] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [speed_dial] destination_number(4455) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->default_caller_id] continue=true
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(emergency_caller_id_name=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(emergency_caller_id_number=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(outbound_caller_id_name=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [outbound_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(outbound_caller_id_number=)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [outbound_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->blacklist_check_outbound] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [blacklist_check_outbound] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(blacklist_result=${blacklist(check inbound_blocked ${caller_id_number})}) IN LINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(blacklist_result=false)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [blacklist_result]=[false]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [blacklist_check_outbound] ${blacklist_result}(false) =~ /^true$/ break=al ways
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->UAT.d1011] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [UAT.d1011] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [UAT.d1011] destination_number(4455) =~ /^(\d{10,11})$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->blacklist_check_inbound] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [blacklist_check_inbound] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action set(blacklist_result=${blacklist(check inbound_blocked ${caller_id_number})}) IN LINE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(blacklist_result=false)
2023-07-11 10:08:19.093900 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [blacklist_result]=[false]
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [blacklist_check_inbound] ${blacklist_result}(false) =~ /^true$/ break=alw ays
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->agent_status] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (FAIL) [agent_status] destination_number(4455) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com parsing [unimrcp.tel4vn.com->unimrcpSTTDeepgram] continue=false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Regex (PASS) [unimrcpSTTDeepgram] destination_number(4455) =~ /^4455$/ break=on-false
Dialplan: sofia/internal/1...@unimrcp.tel4vn.com Action lua(asr_tts_google.lua)
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1...@unimrcp.tel4vn.com) State Change CS_ROUTING -> C S_EXECUTE
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1...@unimrcp.tel4vn.com) State ROUTING going to sleep
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1...@unimrcp.tel4vn.com) Running State Change CS_EXEC UTE (Cur 1 Tot 10)
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1...@unimrcp.tel4vn.com) State EXECUTE
2023-07-11 10:08:19.093900 [DEBUG] mod_sofia.c:209 sofia/internal/1...@unimrcp.tel4vn.com SOFIA EXECUTE
2023-07-11 10:08:19.093900 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1...@unimrcp.tel4vn.com Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(caller_id_number=101)
2023-07-11 10:08:19.113902 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [caller_id_number]=[101]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com export(origination_callee_id_name=4455)
2023-07-11 10:08:19.113902 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[4455]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(RFC2822_DATE=Tue, 11 Jul 2023 10:08:19 +0700)
2023-07-11 10:08:19.113902 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [RFC2822_DATE]=[Tue, 11 Jul 2023 10:08: 19 +0700]
2023-07-11 10:08:19.113902 [INFO] switch_ivr_async.c:2855 Sending early media
2023-07-11 10:08:19.133953 [DEBUG] switch_core_media.c:8675 AUDIO RTP [sofia/internal/1...@unimrcp.tel4vn.com] 10.127.17.16 port 30770 - > 192.168.2.34 port 4000 codec: 8 ms: 20
2023-07-11 10:08:19.153928 [DEBUG] switch_rtp.c:4478 Starting timer [soft] 160 bytes per 20ms
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:8897 Activating RTCP PORT 4001
2023-07-11 10:08:19.153928 [DEBUG] switch_rtp.c:4876 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 4001
2023-07-11 10:08:19.153928 [DEBUG] switch_rtp.c:2638 Setting RTCP remote addr to 192.168.2.34:4001 2
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:8989 sofia/internal/1...@unimrcp.tel4vn.com Set 2833 dtmf send payload to 101
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:8996 sofia/internal/1...@unimrcp.tel4vn.com Set 2833 dtmf receive payload to 101
2023-07-11 10:08:19.153928 [DEBUG] switch_core_media.c:9019 sofia/internal/1...@unimrcp.tel4vn.com Set rtp dtmf delay to 40
2023-07-11 10:08:19.153928 [DEBUG] mod_sofia.c:2593 Ring SDP:
v=0
o=FreeSWITCH 1689014129 1689014130 IN IP4 113.164.246.16
s=FreeSWITCH
c=IN IP4 113.164.246.16
t=0 0
m=audio 30770 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=rtcp:30771 IN IP4 113.164.246.16
2023-07-11 10:08:19.153928 [NOTICE] mod_sofia.c:2596 Pre-Answer sofia/internal/1...@unimrcp.tel4vn.com!
2023-07-11 10:08:19.153928 [DEBUG] switch_channel.c:3565 (sofia/internal/1...@unimrcp.tel4vn.com) Callstate Change RINGING -> EARLY
2023-07-11 10:08:19.273887 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [early][183]
2023-07-11 10:08:19.293938 [DEBUG] switch_ivr_async.c:1427 Record session sample rate: 8000 -> 8000
2023-07-11 10:08:19.293938 [DEBUG] switch_core_media_bug.c:970 Attaching BUG to sofia/internal/1...@unimrcp.tel4vn.com
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com set(+OK Success
)
2023-07-11 10:08:19.293938 [DEBUG] mod_dptools.c:1685 SET sofia/internal/1...@unimrcp.tel4vn.com [+OK Success
]=[UNDEF]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com hash(insert/unimrcp.tel4vn.com-last_dial/101/4455)
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com lua(asr_tts_google.lua)
2023-07-11 10:08:19.373945 [DEBUG] switch_core_media.c:8657 Audio params are unchanged for sofia/internal/1...@unimrcp.tel4vn.com.
2023-07-11 10:08:19.373945 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/1...@unimrcp.tel4vn.com:
v=0
o=FreeSWITCH 1689014129 1689014131 IN IP4 113.164.246.16
s=FreeSWITCH
c=IN IP4 113.164.246.16
t=0 0
m=audio 30770 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=rtcp:30771 IN IP4 113.164.246.16
2023-07-11 10:08:19.373945 [NOTICE] switch_cpp.cpp:703 Channel [sofia/internal/1...@unimrcp.tel4vn.com] has been answered
2023-07-11 10:08:19.373945 [DEBUG] switch_channel.c:3865 (sofia/internal/1...@unimrcp.tel4vn.com) Callstate Change EARLY -> ACTIVE
2023-07-11 10:08:19.373945 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [completed][200]
2023-07-11 10:08:19.373945 [INFO] switch_rtp.c:7170 Auto Changing audio RTCP port from 192.168.2.34:4001 to 113.161.95.53:41122
2023-07-11 10:08:19.373945 [DEBUG] switch_rtp.c:2638 Setting RTCP remote addr to 113.161.95.53:41122 2
2023-07-11 10:08:19.373945 [DEBUG] switch_ivr_async.c:1717 No silence detection configured; assuming start of speech
2023-07-11 10:08:19.413908 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMA:8
2023-07-11 10:08:19.433991 [DEBUG] switch_rtp.c:1923 rtcp_stats_init: audio ssrc[1868191256] base_seq[24477]
2023-07-11 10:08:19.593948 [INFO] switch_rtp.c:7753 Auto Changing audio port from 192.168.2.34:4000 to 113.161.95.53:41121
2023-07-11 10:08:19.693916 [DEBUG] sofia.c:7406 Channel sofia/internal/1...@unimrcp.tel4vn.com entering state [ready][200]
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com playback(/usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-welcome_to_free switch.wav)
2023-07-11 10:08:20.393945 [DEBUG] switch_ivr_play_say.c:1486 Codec Activated L16@8000hz 1 channels 20ms
2023-07-11 10:08:21.953923 [INFO] mod_shout.c:332 LAME 3.100 64bits (http://lame.sf.net)
2023-07-11 10:08:21.953923 [INFO] mod_shout.c:332 polyphase lowpass filter disabled
2023-07-11 10:08:23.013952 [DEBUG] switch_ivr_play_say.c:1931 done playing file /usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr- welcome_to_freeswitch.wav
EXECUTE [depth=0] sofia/internal/1...@unimrcp.tel4vn.com play_and_detect_speech(/usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-p lease_enter_the_number_where_we_can_reach_you.wav detect:unimrcp:uni2 {start-input-timers=false,input-timeout=70000,recognition-timeout =70000}builtin:speech/transcribe?deepgram.model=phonecall;speech-start-timeout=100)
2023-07-11 10:08:24.573904 [INFO] mod_unimrcp.c:3128 asr_handle: name = unimrcp, codec = (null), rate = 8000, grammar = (null), param = uni2
2023-07-11 10:08:24.573904 [INFO] mod_unimrcp.c:3130 codec = L16, rate = 8000, dest = (null)
2023-07-11 10:08:24.573904 [DEBUG] mod_unimrcp.c:684 (ASR-7) audio queue created
2023-07-11 10:08:24.573904 [NOTICE] mrcp_application.c:96 (ASR-7) Create MRCP Handle 0x7f46c0122480 [uni2]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:133 (ASR-7) Create Channel ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46c00c93f0;4;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46c00c93f0;4;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:387 (ASR-7) Receive App Request ASR-7 <new> [2]
2023-07-11 10:08:24.573904 [INFO] mrcp_client.c:700 (ASR-7) Add MRCP Handle ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:1283 (ASR-7) Dispatch App Request ASR-7 <new> [2]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f46780181e0;1;0]
2023-07-11 10:08:24.573904 [NOTICE] mrcp_client_session.c:719 (ASR-7) Add Control Channel ASR-7 <new@speechrecog>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:745 (ASR-7) Add Media Termination ASR-7 <new@media-tm>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:777 (ASR-7) Add Media Termination ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f4678004fe0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f46780181e0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46740019a0;2;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46740019a0;2;0]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:294 (ASR-7) Control Channel Added ASR-7 <new@speechrecog>
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f4678004fe0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] mpf_context.c:182 () Add Media Context ASR-7
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46640062f0;3;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46640062f0;3;0]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:944 (ASR-7) Media Termination Added ASR-7 <new@media-tm>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:944 (ASR-7) Media Termination Added ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:411 (ASR-7) Send Offer ASR-7 <new> [c:1 a:1 v:0] to 42.96.44.195:8060
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:354 (ASR-7) Local SDP ASR-7 <new>
v=0
o=FreeSWITCH 0 0 IN IP4 127.0.1.1
s=-
c=IN IP4 127.0.1.1
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4014 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=mid:1
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 0 INVITE sent [uni2]
2023-07-11 10:08:24.573904 [NOTICE] mrcp_sofiasip_client_agent.c:547 (ASR-7) SIP Call State ASR-7 [calling]
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_r_invite] Status 503 Service Unavailable [ uni2]
2023-07-11 10:08:24.573904 [INFO] mrcp_sofiasip_client_agent.c:609 () Receive SIP Event [nua_i_state] Status 503 Service Unavailable [u ni2]
2023-07-11 10:08:24.573904 [NOTICE] mrcp_sofiasip_client_agent.c:547 (ASR-7) SIP Call State ASR-7 [terminated]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f4654022f80;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f4654022f80;1;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:151 (ASR-7) Receive Answer ASR-7 <new> [c:0 a:0 v:0] Status 503
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:455 (ASR-7) Raise App Response ASR-7 <new> [2] FAILURE [2]
2023-07-11 10:08:24.573904 [ERR] mod_unimrcp.c:1914 (ASR-7) RECOGNIZER channel error!
2023-07-11 10:08:24.573904 [DEBUG] mod_unimrcp.c:1578 (ASR-7) CLOSED ==> ERROR
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] mod_unimrcp.c:1062 (ASR-7) Terminating MRCP session
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46c0081f10;4;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46c0081f10;4;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:387 (ASR-7) Receive App Request ASR-7 <new> [1]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:1283 (ASR-7) Dispatch App Request ASR-7 <new> [1]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:833 (ASR-7) Terminate Session ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:854 (ASR-7) Remove Control Channel ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7f46780140e0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:864 (ASR-7) Subtract Media Termination ASR-7 <new@media-tm>
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:885 (ASR-7) Subtract Media Termination ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MediaEngine] [0x7f46640062f0;1;0]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f46740010a0;1;1]
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f46740010a0;1;1]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7f46780140e0;1;0]
2023-07-11 10:08:24.573904 [INFO] mrcp_client_session.c:209 (ASR-7) Session Terminated ASR-7 <new>
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f4674001a20;2;2]
2023-07-11 10:08:24.573904 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2023-07-11 10:08:24.573904 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f4674001a20;2;2]
2023-07-11 10:08:24.573904 [DEBUG] mrcp_client_session.c:331 (ASR-7) Control Channel Removed ASR-7 <new@speechrecog>
2023-07-11 10:08:24.573904 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2023-07-11 10:08:24.593914 [DEBUG] apt_task.c:337 () Process Message [MediaEngine] [0x7f46640062f0;1;0]
2023-07-11 10:08:24.593914 [DEBUG] mpf_context.c:238 () Remove Media Context ASR-7
2023-07-11 10:08:24.593914 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7f4678004fe0;3;0]
2023-07-11 10:08:24.593914 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7f4678004fe0;3;0]
2023-07-11 10:08:24.593914 [DEBUG] mrcp_client_session.c:1014 (ASR-7) Media Termination Subtracted ASR-7 <new@media-tm>
2023-07-11 10:08:24.593914 [DEBUG] mrcp_client_session.c:1014 (ASR-7) Media Termination Subtracted ASR-7 <new@rtp-tm>
2023-07-11 10:08:24.593914 [INFO] mrcp_client.c:710 (ASR-7) Remove MRCP Handle ASR-7 <new>
2023-07-11 10:08:24.593914 [INFO] mrcp_client_session.c:455 (ASR-7) Raise App Response ASR-7 <new> [1] SUCCESS [0]
2023-07-11 10:08:24.593914 [DEBUG] mod_unimrcp.c:1829 (ASR-7) Destroying MRCP session
2023-07-11 10:08:24.593914 [NOTICE] mrcp_application.c:182 (ASR-7) Destroy MRCP Handle ASR-7
2023-07-11 10:08:24.593914 [DEBUG] mod_unimrcp.c:1578 (ASR-7) ERROR ==> CLOSED
2023-07-11 10:08:24.593914 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
Vahagn Kocharyan
Jul 16, 2023, 4:56:51 PM7/16/23
to UniMRCP
Hi
Nguyễn Võ Duy Phùng
investigating your shared logs i have found that you have misconfiguration
1. freeswitch ip in configuration file(mrcp_profile) must be set to local ip, see example
<param name="client-ip" value="10.128.0.5"/>
2.if your unimrcp server is not in same subnet you must add set rtp-ext-ip as freeswitch public ip
2.if your unimrcp server is not in same subnet you must add set rtp-ext-ip as freeswitch public ip
<param name="rtp-ext-ip" value="public ip"/>
3.set freeswitch sip external ip in freeswitch configuration to freeswitch public ip
4.set rtp-ext-ip,sip-ext-ip in unimrcpserver.xml
5.try umc app located in /opt/unimrcp/bin directory to ensur that all works in unimrcp side or share unimrcp logs also
Thanks
Nguyễn Võ Duy Phùng
Aug 3, 2023, 11:17:29 AM8/3/23
to UniMRCP
Good day
Vahagn Kocharyan
I really appreciate what you support me in this post. But my case have been put off temporarily for some work reason. Maybe I will fulfill your tutorial in the next future.
Many thanks for your support.
Reply all
Reply to author
Forward
0 new messages