Hello Everyone I am stuck with this error from a week. I have tried almost everything which I know but it didn't work for me. I really need help of you guys.
Here I am adding the completed logs.
2022-10-06 17:15:36.428918 89.33% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/100@206.189.143.121 [7e4a1a4e-459a-11ed-a296-c722fa9baa5d]
2022-10-06 17:15:36.428918 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_NEW (Cur 1 Tot 20)
2022-10-06 17:15:36.428918 89.33% [INFO] sofia.c:10462 sofia/internal/100@206.189.143.121 receiving invite from 122.177.110.202:33014 version: 1.10.7 -release 64bit call-id: 03a0c3afa8a74cc9b9506c213b8fe1f8
2022-10-06 17:15:36.428918 89.33% [DEBUG] sofia.c:10556 verifying acl "providers" for ip/port 122.177.110.202:0.
2022-10-06 17:15:36.428918 89.33% [DEBUG] sofia.c:2419 detaching session 7e4a1a4e-459a-11ed-a296-c722fa9baa5d
2022-10-06 17:15:36.428918 89.33% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/100@206.189.143.121) State NEW
2022-10-06 17:15:36.548946 89.33% [DEBUG] sofia.c:2532 Re-attaching to session 7e4a1a4e-459a-11ed-a296-c722fa9baa5d
2022-10-06 17:15:36.548946 89.33% [INFO] sofia.c:10462 sofia/internal/100@206.189.143.121 receiving invite from 122.177.110.202:33014 version: 1.10.7 -release 64bit call-id: 03a0c3afa8a74cc9b9506c213b8fe1f8
2022-10-06 17:15:36.548946 89.33% [DEBUG] sofia.c:10556 verifying acl "providers" for ip/port 122.177.110.202:0.
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:11672 Setting NAT mode based on via received
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:7499 Channel sofia/internal/100@206.189.143.121 entering state [received][100]
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:7509 Remote SDP:
v=0
o=- 3874085136 3874085136 IN IP4 192.168.1.5
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4002 RTP/SAVP 8 0 101
c=IN IP4 192.168.1.5
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:4003 IN IP4 192.168.1.5
a=ssrc:1759925794 cname:7940006d23185534
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:OyMTArRf4J6RINKCFUR6FWAIOrBRBjf1n1ZUs5za
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:7912 (sofia/internal/100@206.189.143.121) State Change CS_NEW -> CS_INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_INIT (Cur 1 Tot 20)
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/100@206.189.143.121) State INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_sofia.c:97 sofia/internal/100@206.189.143.121 SOFIA INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:40 sofia/internal/100@206.189.143.121 Standard INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100@206.189.143.121) State Change CS_INIT -> CS_ROUTING
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/100@206.189.143.121) State INIT going to sleep
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_ROUTING (Cur 1 Tot 20)
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_channel.c:2380 (sofia/internal/100@206.189.143.121) Callstate Change DOWN -> RINGING
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/100@206.189.143.121) State ROUTING
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_sofia.c:158 sofia/internal/100@206.189.143.121 SOFIA ROUTING
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:230 sofia/internal/100@206.189.143.121 Standard ROUTING
2022-10-06 17:15:36.568912 89.33% [INFO] mod_dialplan_xml.c:639 Processing 100 <100>->18089990848 in context 206.189.143.121
2022-10-06 17:15:36.568912 89.33% [NOTICE] switch_cpp.cpp:1465 [xml_handler] multiple key:dialplan:206.189.143.121
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->caller-details] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(caller_destination=18089990848)
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [caller_destination]=[18089990848]
Dialplan: sofia/internal/100@206.189.143.121 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(caller_id_name=100)
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [caller_id_name]=[100]
Dialplan: sofia/internal/100@206.189.143.121 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->user_exists] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(user_exists=false)
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [user_exists]=[false]
Dialplan: sofia/internal/100@206.189.143.121 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(from_user_exists=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [from_user_exists]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->caller-details] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [caller-details] ${caller_destination}(18089990848) =~ /^$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->global-variables] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->domain-variables] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/100@206.189.143.121 Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(operator=1000)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [operator]=[1000]
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->is_loopback] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->call-direction] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 export(call_direction=local)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->user_record] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_session=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_session]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(from_user_record=all)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [from_user_record]=[all]
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_session=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_session]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] destination_number(18089990848) =~ /^(?
?!\*).|\*59|\*\*|\*8|\*67|\*69)+$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_path=/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_path]=[/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06]
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_name=${uuid}.${record_ext}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_name=7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_name]=[7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav]
Dialplan: sofia/internal/100@206.189.143.121 Action mkdir(${record_path})
Dialplan: sofia/internal/100@206.189.143.121 Action set(recording_follow_transfer=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(recording_follow_transfer=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [recording_follow_transfer]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Action bind_digit_action(local,*5,api:uuid_record,${uuid} mask ${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext},both,self)
Dialplan: sofia/internal/100@206.189.143.121 Action bind_digit_action(local,*6,api:uuid_record,${uuid} unmask ${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext},both,self)
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_append=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_append=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_append]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_in_progress=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_in_progress=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_in_progress]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Action set(RECORD_ANSWER_REQ=true)
Dialplan: sofia/internal/100@206.189.143.121 Action record_session(${record_path}/${record_name})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->rtp_has_crypto] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [rtp_has_crypto] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->redial] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [redial] destination_number(18089990848) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/100@206.189.143.121 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->speed_dial] continue=false
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [speed_dial] destination_number(18089990848) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->user_hold_music] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->default_caller_id] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [default_caller_id] ${call_direction}(local) =~ /outbound/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->Twilio.129d229d2d4] continue=false
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [Twilio.129d229d2d4] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [Twilio.129d229d2d4] destination_number(18089990848) =~ /^\+?1?([2-9]\d{2}[2-9]\d{2}\d{4})$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/100@206.189.143.121 Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 export(call_direction=outbound)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/100@206.189.143.121 Action unset(call_timeout)
Dialplan: sofia/internal/100@206.189.143.121 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/100@206.189.143.121 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/100@206.189.143.121 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/100@206.189.143.121 Action set(inherit_codec=true)
Dialplan: sofia/internal/100@206.189.143.121 Action set(ignore_display_updates=true)
Dialplan: sofia/internal/100@206.189.143.121 Action set(callee_id_number=8089990848)
Dialplan: sofia/internal/100@206.189.143.121 Action set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
Dialplan: sofia/internal/100@206.189.143.121 Action bridge(sofia/gateway/1d941d16-bd87-4b3c-a37c-4af67fe97fdf/18089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/100@206.189.143.121) State Change CS_ROUTING -> CS_EXECUTE
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/100@206.189.143.121) State ROUTING going to sleep
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_EXECUTE (Cur 1 Tot 20)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/100@206.189.143.121) State EXECUTE
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:213 sofia/internal/100@206.189.143.121 SOFIA EXECUTE
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:323 sofia/internal/100@206.189.143.121 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(caller_id_number=100)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [caller_id_number]=[100]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(RFC2822_DATE=Thu, 06 Oct 2022 17:15:36 +0000)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [RFC2822_DATE]=[Thu, 06 Oct 2022 17:15:36 +0000]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 export(origination_callee_id_name=18089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [origination_callee_id_name]=[18089990848]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 mkdir(/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:669 sofia/internal/100@206.189.143.121 MKDIR: /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 bind_digit_action(local,*5,api:uuid_record,7e4a1a4e-459a-11ed-a296-c722fa9baa5d mask /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06/7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav,both,self)
2022-10-06 17:15:36.588905 89.33% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'local'
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *5/local/0 callback: 0x7f4829489fd0 data: 0x7f48140368b0
2022-10-06 17:15:36.588905 89.33% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'local'
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *5/local/0 callback: 0x7f4829489fd0 data: 0x7f48140369a8
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 bind_digit_action(local,*6,api:uuid_record,7e4a1a4e-459a-11ed-a296-c722fa9baa5d unmask /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06/7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav,both,self)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *6/local/0 callback: 0x7f4829489fd0 data: 0x7f4814036ce0
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *6/local/0 callback: 0x7f4829489fd0 data: 0x7f4814036dd8
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(RECORD_ANSWER_REQ=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [RECORD_ANSWER_REQ]=[true]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_session.c:2795 Application record_session Requires media! pre_answering channel sofia/internal/100@206.189.143.121
2022-10-06 17:15:36.588905 89.33% [INFO] switch_core_session.c:2797 Sending early media
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_256_GCM]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_128_GCM]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1844 Found suite AES_CM_128_HMAC_SHA1_80
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1914 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1230 Set Local audio crypto Key [1 AES_CM_128_HMAC_SHA1_80 inline:96nZPjAaAEpC0cy5ZBe2igkoXFXT/PEJpLRfb6zh]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:3870 Set Codec sofia/internal/100@206.189.143.121 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_codec.c:111 sofia/internal/100@206.189.143.121 Original read codec set to PCMA:8
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5973 sofia/internal/100@206.189.143.121 Set 2833 dtmf send payload to 101 recv payload to 101
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:8777 AUDIO RTP [sofia/internal/100@206.189.143.121] 206.189.143.121 port 24798 -> 192.168.1.5 port 4002 codec: 8 ms: 20
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:8997 Activating RTCP PORT 4003
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_rtp.c:5017 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 4003
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 192.168.1.5:4003 2
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:9089 sofia/internal/100@206.189.143.121 Set 2833 dtmf send payload to 101
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:9096 sofia/internal/100@206.189.143.121 Set 2833 dtmf receive payload to 101
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:9119 sofia/internal/100@206.189.143.121 Set rtp dtmf delay to 40
2022-10-06 17:15:36.588905 89.33% [INFO] switch_rtp.c:4423 Activating audio Secure RTP SEND
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2022-10-06 17:15:36.588905 89.33% [INFO] switch_rtp.c:4401 Activating audio Secure RTP RECV
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2022-10-06 17:15:36.588905 89.33% [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/100@206.189.143.121!
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:3622 (sofia/internal/100@206.189.143.121) Callstate Change RINGING -> EARLY
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:8759 Audio params are unchanged for sofia/internal/100@206.189.143.121.
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:2610 Ring SDP:
v=0
o=FreeSWITCH 1665051738 1665051739 IN IP4 206.189.143.121
s=FreeSWITCH
c=IN IP4 206.189.143.121
t=0 0
m=audio 24798 RTP/SAVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
a=rtcp:24799 IN IP4 206.189.143.121
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:96nZPjAaAEpC0cy5ZBe2igkoXFXT/PEJpLRfb6zh
2022-10-06 17:15:36.588905 89.33% [DEBUG] sofia.c:7499 Channel sofia/internal/100@206.189.143.121 entering state [early][183]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 record_session(/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06/7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav)
2022-10-06 17:15:36.588905 89.33% [ERR] switch_ivr_async.c:3116 Error creating /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 hash(insert/206.189.143.121-last_dial/100/18089990848)
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(sip_h_X-accountcode=206.189.143.121)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [sip_h_X-accountcode]=[206.189.143.121]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 unset(call_timeout)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1830 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(hangup_after_bridge=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(effective_caller_id_name=Call Center)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [effective_caller_id_name]=[Call Center]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(effective_caller_id_number=19793644935)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [effective_caller_id_number]=[19793644935]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(inherit_codec=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(ignore_display_updates=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(callee_id_number=8089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [callee_id_number]=[8089990848]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 bridge(sofia/gateway/1d941d16-bd87-4b3c-a37c-4af67fe97fdf/18089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [domain_name]=[206.189.143.121] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [origination_callee_id_name]=[18089990848] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-10-06 17:15:36.588905 89.33% [NOTICE] switch_channel.c:1123 New Channel sofia/external/18089990848 [7e62bb6c-459a-11ed-a2be-c722fa9baa5d]
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:5121 (sofia/external/18089990848) State Change CS_NEW -> CS_INIT
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_INIT (Cur 2 Tot 21)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/external/18089990848) State INIT
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:97 sofia/external/18089990848 SOFIA INIT
2022-10-06 17:15:36.588905 89.33% [INFO] sofia_glue.c:1651 sofia/external/18089990848 sending invite call-id: (null)
2022-10-06 17:15:36.588905 89.33% [DEBUG] sofia_glue.c:1654 sofia/external/18089990848 sending invite version: 1.10.7 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1665051736 1665051737 IN IP4 206.189.143.121
s=FreeSWITCH
c=IN IP4 206.189.143.121
t=0 0
m=audio 24800 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSuppff - - - -
a=ptime:20
a=sendrecv
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:40 sofia/external/18089990848 Standard INIT
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:48 (sofia/external/18089990848) State Change CS_INIT -> CS_ROUTING
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/external/18089990848) State INIT going to sleep
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_ROUTING (Cur 2 Tot 21)
2022-10-06 17:15:36.588905 89.33% [DEBUG] sofia.c:7499 Channel sofia/external/18089990848 entering state [calling][0]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/external/18089990848) State ROUTING
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:158 sofia/external/18089990848 SOFIA ROUTING
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_originate.c:67 (sofia/external/18089990848) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/external/18089990848) State ROUTING going to sleep
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 21)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:659 (sofia/external/18089990848) State CONSUME_MEDIA
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:659 (sofia/external/18089990848) State CONSUME_MEDIA going to sleep
2022-10-06 17:15:36.688901 89.33% [INFO] switch_rtp.c:7310 Auto Changing audio RTCP port from 192.168.1.5:4003 to 122.177.110.202:29474
2022-10-06 17:15:36.688901 89.33% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 122.177.110.202:29474 2
2022-10-06 17:15:36.708928 89.33% [DEBUG] switch_rtp.c:1982 rtcp_stats_init: audio ssrc[1759925794] base_seq[30335]
2022-10-06 17:15:36.948921 89.33% [INFO] switch_rtp.c:7894 Auto Changing audio port from 192.168.1.5:4002 to 122.177.110.202:16990
2022-10-06 17:15:37.048922 89.33% [DEBUG] sofia.c:7499 Channel sofia/external/18089990848 entering state [calling][0]
2022-10-06 17:15:37.289124 89.33% [DEBUG] sofia.c:7499 Channel sofia/external/18089990848 entering state [terminated][488]
2022-10-06 17:15:37.289124 89.33% [NOTICE] sofia.c:8738 Hangup sofia/external/18089990848 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_HANGUP (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:844 (sofia/external/18089990848) Callstate Change DOWN -> HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/18089990848) State HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:468 Channel sofia/external/18089990848 hanging up, cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:59 sofia/external/18089990848 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/18089990848) State HANGUP going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:616 (sofia/external/18089990848) State Change CS_HANGUP -> CS_REPORTING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_REPORTING (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/18089990848) State REPORTING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:168 sofia/external/18089990848 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/18089990848) State REPORTING going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:607 (sofia/external/18089990848) State Change CS_REPORTING -> CS_DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_session.c:1753 Session 21 (sofia/external/18089990848) Locked, Waiting on external entities
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2022-10-06 17:15:37.289124 89.33% [INFO] mod_dptools.c:3653 Originate Failed. Cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_channel.c:4981 Continue on fail [1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]: Cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_state_machine.c:382 sofia/internal/100@206.189.143.121 has executed the last dialplan instruction, hanging up.
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/100@206.189.143.121 [CS_EXECUTE] [NORMAL_CLEARING]
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/100@206.189.143.121) State EXECUTE going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_HANGUP (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/100@206.189.143.121) Callstate Change EARLY -> HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/100@206.189.143.121) State HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:462 sofia/internal/100@206.189.143.121 Overriding SIP cause 480 with 488 from the other leg
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:468 Channel sofia/internal/100@206.189.143.121 hanging up, cause: NORMAL_CLEARING
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 488
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:59 sofia/internal/100@206.189.143.121 Standard HANGUP, cause: NORMAL_CLEARING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/100@206.189.143.121) State HANGUP going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/100@206.189.143.121) State Change CS_HANGUP -> CS_REPORTING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_REPORTING (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/100@206.189.143.121) State REPORTING
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_session.c:1771 Session 21 (sofia/external/18089990848) Ended
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_session.c:1775 Close Channel sofia/external/18089990848 [CS_DESTROY]
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:735 (sofia/external/18089990848) Running State Change CS_DESTROY (Cur 1 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/external/18089990848) State DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:379 sofia/external/18089990848 SOFIA DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:175 sofia/external/18089990848 Standard DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/external/18089990848) State DESTROY going to sleep
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:168 sofia/internal/100@206.189.143.121 Standard REPORTING, cause: NORMAL_CLEARING
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/100@206.189.143.121) State REPORTING going to sleep
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/100@206.189.143.121) State Change CS_REPORTING -> CS_DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_session.c:1753 Session 20 (sofia/internal/100@206.189.143.121) Locked, Waiting on external entities
2022-10-06 17:15:37.408911 89.33% [NOTICE] switch_core_session.c:1771 Session 20 (sofia/internal/100@206.189.143.121) Ended
2022-10-06 17:15:37.408911 89.33% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/100@206.189.143.121 [CS_DESTROY]
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/100@206.189.143.121) Running State Change CS_DESTROY (Cur 0 Tot 21)
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/100@206.189.143.121) State DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] mod_sofia.c:379 sofia/internal/100@206.189.143.121 SOFIA DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:175 sofia/internal/100@206.189.143.121 Standard DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/100@206.189.143.121) State DESTROY going to sleep
Here I am adding the completed logs.
2022-10-06 17:15:36.428918 89.33% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/100@206.189.143.121 [7e4a1a4e-459a-11ed-a296-c722fa9baa5d]
2022-10-06 17:15:36.428918 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_NEW (Cur 1 Tot 20)
2022-10-06 17:15:36.428918 89.33% [INFO] sofia.c:10462 sofia/internal/100@206.189.143.121 receiving invite from 122.177.110.202:33014 version: 1.10.7 -release 64bit call-id: 03a0c3afa8a74cc9b9506c213b8fe1f8
2022-10-06 17:15:36.428918 89.33% [DEBUG] sofia.c:10556 verifying acl "providers" for ip/port 122.177.110.202:0.
2022-10-06 17:15:36.428918 89.33% [DEBUG] sofia.c:2419 detaching session 7e4a1a4e-459a-11ed-a296-c722fa9baa5d
2022-10-06 17:15:36.428918 89.33% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/100@206.189.143.121) State NEW
2022-10-06 17:15:36.548946 89.33% [DEBUG] sofia.c:2532 Re-attaching to session 7e4a1a4e-459a-11ed-a296-c722fa9baa5d
2022-10-06 17:15:36.548946 89.33% [INFO] sofia.c:10462 sofia/internal/100@206.189.143.121 receiving invite from 122.177.110.202:33014 version: 1.10.7 -release 64bit call-id: 03a0c3afa8a74cc9b9506c213b8fe1f8
2022-10-06 17:15:36.548946 89.33% [DEBUG] sofia.c:10556 verifying acl "providers" for ip/port 122.177.110.202:0.
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:11672 Setting NAT mode based on via received
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:7499 Channel sofia/internal/100@206.189.143.121 entering state [received][100]
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:7509 Remote SDP:
v=0
o=- 3874085136 3874085136 IN IP4 192.168.1.5
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4002 RTP/SAVP 8 0 101
c=IN IP4 192.168.1.5
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:4003 IN IP4 192.168.1.5
a=ssrc:1759925794 cname:7940006d23185534
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:OyMTArRf4J6RINKCFUR6FWAIOrBRBjf1n1ZUs5za
2022-10-06 17:15:36.568912 89.33% [DEBUG] sofia.c:7912 (sofia/internal/100@206.189.143.121) State Change CS_NEW -> CS_INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_INIT (Cur 1 Tot 20)
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/100@206.189.143.121) State INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_sofia.c:97 sofia/internal/100@206.189.143.121 SOFIA INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:40 sofia/internal/100@206.189.143.121 Standard INIT
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100@206.189.143.121) State Change CS_INIT -> CS_ROUTING
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/100@206.189.143.121) State INIT going to sleep
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_ROUTING (Cur 1 Tot 20)
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_channel.c:2380 (sofia/internal/100@206.189.143.121) Callstate Change DOWN -> RINGING
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/100@206.189.143.121) State ROUTING
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_sofia.c:158 sofia/internal/100@206.189.143.121 SOFIA ROUTING
2022-10-06 17:15:36.568912 89.33% [DEBUG] switch_core_state_machine.c:230 sofia/internal/100@206.189.143.121 Standard ROUTING
2022-10-06 17:15:36.568912 89.33% [INFO] mod_dialplan_xml.c:639 Processing 100 <100>->18089990848 in context 206.189.143.121
2022-10-06 17:15:36.568912 89.33% [NOTICE] switch_cpp.cpp:1465 [xml_handler] multiple key:dialplan:206.189.143.121
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->caller-details] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(caller_destination=18089990848)
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [caller_destination]=[18089990848]
Dialplan: sofia/internal/100@206.189.143.121 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(caller_id_name=100)
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [caller_id_name]=[100]
Dialplan: sofia/internal/100@206.189.143.121 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->user_exists] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(user_exists=false)
2022-10-06 17:15:36.568912 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [user_exists]=[false]
Dialplan: sofia/internal/100@206.189.143.121 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(from_user_exists=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [from_user_exists]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->caller-details] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [caller-details] ${caller_destination}(18089990848) =~ /^$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->global-variables] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->domain-variables] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/100@206.189.143.121 Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(operator=1000)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [operator]=[1000]
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->is_loopback] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->call-direction] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 export(call_direction=local)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->user_record] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_session=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_session]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(from_user_record=all)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [from_user_record]=[all]
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_session=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_session=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_session]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [user_record] destination_number(18089990848) =~ /^(?
?!\*).|\*59|\*\*|\*8|\*67|\*69)+$/ break=on-falseDialplan: sofia/internal/100@206.189.143.121 Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_path=/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_path]=[/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06]
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_name=${uuid}.${record_ext}) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_name=7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_name]=[7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav]
Dialplan: sofia/internal/100@206.189.143.121 Action mkdir(${record_path})
Dialplan: sofia/internal/100@206.189.143.121 Action set(recording_follow_transfer=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(recording_follow_transfer=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [recording_follow_transfer]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Action bind_digit_action(local,*5,api:uuid_record,${uuid} mask ${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext},both,self)
Dialplan: sofia/internal/100@206.189.143.121 Action bind_digit_action(local,*6,api:uuid_record,${uuid} unmask ${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}/${uuid}.${record_ext},both,self)
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_append=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_append=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_append]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Action set(record_in_progress=true) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(record_in_progress=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [record_in_progress]=[true]
Dialplan: sofia/internal/100@206.189.143.121 Action set(RECORD_ANSWER_REQ=true)
Dialplan: sofia/internal/100@206.189.143.121 Action record_session(${record_path}/${record_name})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->rtp_has_crypto] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [rtp_has_crypto] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->redial] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [redial] destination_number(18089990848) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/100@206.189.143.121 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->speed_dial] continue=false
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [speed_dial] destination_number(18089990848) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->user_hold_music] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->default_caller_id] continue=true
Dialplan: sofia/internal/100@206.189.143.121 Regex (FAIL) [default_caller_id] ${call_direction}(local) =~ /outbound/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 parsing [206.189.143.121->Twilio.129d229d2d4] continue=false
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [Twilio.129d229d2d4] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Regex (PASS) [Twilio.129d229d2d4] destination_number(18089990848) =~ /^\+?1?([2-9]\d{2}[2-9]\d{2}\d{4})$/ break=on-false
Dialplan: sofia/internal/100@206.189.143.121 Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/100@206.189.143.121 Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 export(call_direction=outbound)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/100@206.189.143.121 Action unset(call_timeout)
Dialplan: sofia/internal/100@206.189.143.121 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/100@206.189.143.121 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/100@206.189.143.121 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/100@206.189.143.121 Action set(inherit_codec=true)
Dialplan: sofia/internal/100@206.189.143.121 Action set(ignore_display_updates=true)
Dialplan: sofia/internal/100@206.189.143.121 Action set(callee_id_number=8089990848)
Dialplan: sofia/internal/100@206.189.143.121 Action set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
Dialplan: sofia/internal/100@206.189.143.121 Action bridge(sofia/gateway/1d941d16-bd87-4b3c-a37c-4af67fe97fdf/18089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/100@206.189.143.121) State Change CS_ROUTING -> CS_EXECUTE
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/100@206.189.143.121) State ROUTING going to sleep
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_EXECUTE (Cur 1 Tot 20)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/100@206.189.143.121) State EXECUTE
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:213 sofia/internal/100@206.189.143.121 SOFIA EXECUTE
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:323 sofia/internal/100@206.189.143.121 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(caller_id_number=100)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [caller_id_number]=[100]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(RFC2822_DATE=Thu, 06 Oct 2022 17:15:36 +0000)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [RFC2822_DATE]=[Thu, 06 Oct 2022 17:15:36 +0000]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 export(origination_callee_id_name=18089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [origination_callee_id_name]=[18089990848]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 mkdir(/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:669 sofia/internal/100@206.189.143.121 MKDIR: /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 bind_digit_action(local,*5,api:uuid_record,7e4a1a4e-459a-11ed-a296-c722fa9baa5d mask /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06/7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav,both,self)
2022-10-06 17:15:36.588905 89.33% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'local'
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *5/local/0 callback: 0x7f4829489fd0 data: 0x7f48140368b0
2022-10-06 17:15:36.588905 89.33% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'local'
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *5/local/0 callback: 0x7f4829489fd0 data: 0x7f48140369a8
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 bind_digit_action(local,*6,api:uuid_record,7e4a1a4e-459a-11ed-a296-c722fa9baa5d unmask /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06/7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav,both,self)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *6/local/0 callback: 0x7f4829489fd0 data: 0x7f4814036ce0
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *6/local/0 callback: 0x7f4829489fd0 data: 0x7f4814036dd8
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(RECORD_ANSWER_REQ=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [RECORD_ANSWER_REQ]=[true]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_session.c:2795 Application record_session Requires media! pre_answering channel sofia/internal/100@206.189.143.121
2022-10-06 17:15:36.588905 89.33% [INFO] switch_core_session.c:2797 Sending early media
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_256_GCM]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AEAD_AES_128_GCM]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1835 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1844 Found suite AES_CM_128_HMAC_SHA1_80
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1914 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:lNXByxe5aKLaFlAMZZm7z3IuLOjIP3vBDTI/wZbM]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:1230 Set Local audio crypto Key [1 AES_CM_128_HMAC_SHA1_80 inline:96nZPjAaAEpC0cy5ZBe2igkoXFXT/PEJpLRfb6zh]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:3870 Set Codec sofia/internal/100@206.189.143.121 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_codec.c:111 sofia/internal/100@206.189.143.121 Original read codec set to PCMA:8
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:5973 sofia/internal/100@206.189.143.121 Set 2833 dtmf send payload to 101 recv payload to 101
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:8777 AUDIO RTP [sofia/internal/100@206.189.143.121] 206.189.143.121 port 24798 -> 192.168.1.5 port 4002 codec: 8 ms: 20
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:8997 Activating RTCP PORT 4003
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_rtp.c:5017 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 4003
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 192.168.1.5:4003 2
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:9089 sofia/internal/100@206.189.143.121 Set 2833 dtmf send payload to 101
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:9096 sofia/internal/100@206.189.143.121 Set 2833 dtmf receive payload to 101
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:9119 sofia/internal/100@206.189.143.121 Set rtp dtmf delay to 40
2022-10-06 17:15:36.588905 89.33% [INFO] switch_rtp.c:4423 Activating audio Secure RTP SEND
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2022-10-06 17:15:36.588905 89.33% [INFO] switch_rtp.c:4401 Activating audio Secure RTP RECV
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2022-10-06 17:15:36.588905 89.33% [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/100@206.189.143.121!
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:3622 (sofia/internal/100@206.189.143.121) Callstate Change RINGING -> EARLY
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_media.c:8759 Audio params are unchanged for sofia/internal/100@206.189.143.121.
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:2610 Ring SDP:
v=0
o=FreeSWITCH 1665051738 1665051739 IN IP4 206.189.143.121
s=FreeSWITCH
c=IN IP4 206.189.143.121
t=0 0
m=audio 24798 RTP/SAVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
a=rtcp:24799 IN IP4 206.189.143.121
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:96nZPjAaAEpC0cy5ZBe2igkoXFXT/PEJpLRfb6zh
2022-10-06 17:15:36.588905 89.33% [DEBUG] sofia.c:7499 Channel sofia/internal/100@206.189.143.121 entering state [early][183]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 record_session(/var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06/7e4a1a4e-459a-11ed-a296-c722fa9baa5d.wav)
2022-10-06 17:15:36.588905 89.33% [ERR] switch_ivr_async.c:3116 Error creating /var/lib/freeswitch/recordings/206.189.143.121/archive/2022/Oct/06
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 hash(insert/206.189.143.121-last_dial/100/18089990848)
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(sip_h_X-accountcode=206.189.143.121)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [sip_h_X-accountcode]=[206.189.143.121]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 unset(call_timeout)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1830 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(hangup_after_bridge=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(effective_caller_id_name=Call Center)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [effective_caller_id_name]=[Call Center]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(effective_caller_id_number=19793644935)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [effective_caller_id_number]=[19793644935]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(inherit_codec=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(ignore_display_updates=true)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(callee_id_number=8089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [callee_id_number]=[8089990848]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_dptools.c:1685 SET sofia/internal/100@206.189.143.121 [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]
EXECUTE [depth=0] sofia/internal/100@206.189.143.121 bridge(sofia/gateway/1d941d16-bd87-4b3c-a37c-4af67fe97fdf/18089990848)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [domain_name]=[206.189.143.121] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_channel.c:1269 sofia/internal/100@206.189.143.121 EXPORTING[export_vars] [origination_callee_id_name]=[18089990848] to event
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-10-06 17:15:36.588905 89.33% [NOTICE] switch_channel.c:1123 New Channel sofia/external/18089990848 [7e62bb6c-459a-11ed-a2be-c722fa9baa5d]
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:5121 (sofia/external/18089990848) State Change CS_NEW -> CS_INIT
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_INIT (Cur 2 Tot 21)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/external/18089990848) State INIT
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:97 sofia/external/18089990848 SOFIA INIT
2022-10-06 17:15:36.588905 89.33% [INFO] sofia_glue.c:1651 sofia/external/18089990848 sending invite call-id: (null)
2022-10-06 17:15:36.588905 89.33% [DEBUG] sofia_glue.c:1654 sofia/external/18089990848 sending invite version: 1.10.7 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1665051736 1665051737 IN IP4 206.189.143.121
s=FreeSWITCH
c=IN IP4 206.189.143.121
t=0 0
m=audio 24800 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp
ff - - - -a=ptime:20
a=sendrecv
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:40 sofia/external/18089990848 Standard INIT
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:48 (sofia/external/18089990848) State Change CS_INIT -> CS_ROUTING
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:624 (sofia/external/18089990848) State INIT going to sleep
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_ROUTING (Cur 2 Tot 21)
2022-10-06 17:15:36.588905 89.33% [DEBUG] sofia.c:7499 Channel sofia/external/18089990848 entering state [calling][0]
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/external/18089990848) State ROUTING
2022-10-06 17:15:36.588905 89.33% [DEBUG] mod_sofia.c:158 sofia/external/18089990848 SOFIA ROUTING
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_ivr_originate.c:67 (sofia/external/18089990848) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:640 (sofia/external/18089990848) State ROUTING going to sleep
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 21)
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:659 (sofia/external/18089990848) State CONSUME_MEDIA
2022-10-06 17:15:36.588905 89.33% [DEBUG] switch_core_state_machine.c:659 (sofia/external/18089990848) State CONSUME_MEDIA going to sleep
2022-10-06 17:15:36.688901 89.33% [INFO] switch_rtp.c:7310 Auto Changing audio RTCP port from 192.168.1.5:4003 to 122.177.110.202:29474
2022-10-06 17:15:36.688901 89.33% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 122.177.110.202:29474 2
2022-10-06 17:15:36.708928 89.33% [DEBUG] switch_rtp.c:1982 rtcp_stats_init: audio ssrc[1759925794] base_seq[30335]
2022-10-06 17:15:36.948921 89.33% [INFO] switch_rtp.c:7894 Auto Changing audio port from 192.168.1.5:4002 to 122.177.110.202:16990
2022-10-06 17:15:37.048922 89.33% [DEBUG] sofia.c:7499 Channel sofia/external/18089990848 entering state [calling][0]
2022-10-06 17:15:37.289124 89.33% [DEBUG] sofia.c:7499 Channel sofia/external/18089990848 entering state [terminated][488]
2022-10-06 17:15:37.289124 89.33% [NOTICE] sofia.c:8738 Hangup sofia/external/18089990848 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_HANGUP (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:844 (sofia/external/18089990848) Callstate Change DOWN -> HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/18089990848) State HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:468 Channel sofia/external/18089990848 hanging up, cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:59 sofia/external/18089990848 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/18089990848) State HANGUP going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:616 (sofia/external/18089990848) State Change CS_HANGUP -> CS_REPORTING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/18089990848) Running State Change CS_REPORTING (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/18089990848) State REPORTING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:168 sofia/external/18089990848 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/18089990848) State REPORTING going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:607 (sofia/external/18089990848) State Change CS_REPORTING -> CS_DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_session.c:1753 Session 21 (sofia/external/18089990848) Locked, Waiting on external entities
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2022-10-06 17:15:37.289124 89.33% [INFO] mod_dptools.c:3653 Originate Failed. Cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_channel.c:4981 Continue on fail [1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]: Cause: INCOMPATIBLE_DESTINATION
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_state_machine.c:382 sofia/internal/100@206.189.143.121 has executed the last dialplan instruction, hanging up.
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/100@206.189.143.121 [CS_EXECUTE] [NORMAL_CLEARING]
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/100@206.189.143.121) State EXECUTE going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_HANGUP (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/100@206.189.143.121) Callstate Change EARLY -> HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/100@206.189.143.121) State HANGUP
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:462 sofia/internal/100@206.189.143.121 Overriding SIP cause 480 with 488 from the other leg
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:468 Channel sofia/internal/100@206.189.143.121 hanging up, cause: NORMAL_CLEARING
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 488
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:59 sofia/internal/100@206.189.143.121 Standard HANGUP, cause: NORMAL_CLEARING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/100@206.189.143.121) State HANGUP going to sleep
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/100@206.189.143.121) State Change CS_HANGUP -> CS_REPORTING
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/100@206.189.143.121) Running State Change CS_REPORTING (Cur 2 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/100@206.189.143.121) State REPORTING
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_session.c:1771 Session 21 (sofia/external/18089990848) Ended
2022-10-06 17:15:37.289124 89.33% [NOTICE] switch_core_session.c:1775 Close Channel sofia/external/18089990848 [CS_DESTROY]
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:735 (sofia/external/18089990848) Running State Change CS_DESTROY (Cur 1 Tot 21)
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/external/18089990848) State DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] mod_sofia.c:379 sofia/external/18089990848 SOFIA DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:175 sofia/external/18089990848 Standard DESTROY
2022-10-06 17:15:37.289124 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/external/18089990848) State DESTROY going to sleep
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:168 sofia/internal/100@206.189.143.121 Standard REPORTING, cause: NORMAL_CLEARING
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/100@206.189.143.121) State REPORTING going to sleep
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/100@206.189.143.121) State Change CS_REPORTING -> CS_DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_session.c:1753 Session 20 (sofia/internal/100@206.189.143.121) Locked, Waiting on external entities
2022-10-06 17:15:37.408911 89.33% [NOTICE] switch_core_session.c:1771 Session 20 (sofia/internal/100@206.189.143.121) Ended
2022-10-06 17:15:37.408911 89.33% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/100@206.189.143.121 [CS_DESTROY]
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/100@206.189.143.121) Running State Change CS_DESTROY (Cur 0 Tot 21)
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/100@206.189.143.121) State DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] mod_sofia.c:379 sofia/internal/100@206.189.143.121 SOFIA DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:175 sofia/internal/100@206.189.143.121 Standard DESTROY
2022-10-06 17:15:37.408911 89.33% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/100@206.189.143.121) State DESTROY going to sleep
