@agree , here is the freeswitch log:
2023-12-01 17:31:14.044453 98.43% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/
2004@domain1.mydomain.com:5061 [f52b6764-ec50-458d-ad4c-a5addd066750]
2023-12-01 17:31:14.044453 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_NEW (Cur 1 Tot 10971)
2023-12-01 17:31:14.044453 98.43% [INFO] sofia.c:10453 sofia/internal/
2004@domain1.mydomain.com:5061 receiving invite from [provider ip]:57352 version: 1.10.9 -release 64bit call-id:
1577120500-27121-19@BJC.BGI.IH.BE
2023-12-01 17:31:14.044453 98.43% [DEBUG] sofia.c:10547 verifying acl "providers" for ip/port [provider ip]:0.
2023-12-01 17:31:14.044453 98.43% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/
2004@domain1.mydomain.com:5061) State NEW
2023-12-01 17:31:14.044453 98.43% [DEBUG] sofia.c:2419 detaching session f52b6764-ec50-458d-ad4c-a5addd066750
2023-12-01 17:31:14.084466 98.43% [DEBUG] sofia.c:2532 Re-attaching to session f52b6764-ec50-458d-ad4c-a5addd066750
2023-12-01 17:31:14.104445 98.43% [INFO] sofia.c:10453 sofia/internal/
2004@domain1.mydomain.com:5061 receiving invite from [provider ip]:57352 version: 1.10.9 -release 64bit call-id:
1577120500-27121-19@BJC.BGI.IH.BE
2023-12-01 17:31:14.104445 98.43% [DEBUG] sofia.c:10547 verifying acl "providers" for ip/port [provider ip]:0.
2023-12-01 17:31:14.104445 98.43% [DEBUG] sofia.c:11668 Setting NAT mode based on via received
2023-12-01 17:31:14.104445 98.43% [DEBUG] sofia.c:7487 Channel sofia/internal/
2004@domain1.mydomain.com:5061 entering state [received][100]
2023-12-01 17:31:14.104445 98.43% [DEBUG] sofia.c:7497 Remote SDP:
v=0
o=2004 8000 8000 IN IP4 192.168.87.14
s=SIP Call
c=IN IP4 192.168.87.14
t=0 0
m=audio 13670 RTP/AVP 0 8 4 18 9 97 2 123 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:2 G726-32/8000
a=rtpmap:123 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2023-12-01 17:31:14.104445 98.43% [DEBUG] sofia.c:7900 (sofia/internal/
2004@domain1.mydomain.com:5061) State Change CS_NEW -> CS_INIT
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_INIT (Cur 1 Tot 10971)
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/
2004@domain1.mydomain.com:5061) State INIT
2023-12-01 17:31:14.104445 98.43% [DEBUG] mod_sofia.c:97 sofia/internal/
2004@domain1.mydomain.com:5061 SOFIA INIT
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:40 sofia/internal/
2004@domain1.mydomain.com:5061 Standard INIT
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/
2004@domain1.mydomain.com:5061) State Change CS_INIT -> CS_ROUTING
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/
2004@domain1.mydomain.com:5061) State INIT going to sleep
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_ROUTING (Cur 1 Tot 10971)
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_channel.c:2380 (sofia/internal/
2004@domain1.mydomain.com:5061) Callstate Change DOWN -> RINGING
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/
2004@domain1.mydomain.com:5061) State ROUTING
2023-12-01 17:31:14.104445 98.43% [DEBUG] mod_sofia.c:158 sofia/internal/
2004@domain1.mydomain.com:5061 SOFIA ROUTING
2023-12-01 17:31:14.104445 98.43% [DEBUG] switch_core_state_machine.c:230 sofia/internal/
2004@domain1.mydomain.com:5061 Standard ROUTING
2023-12-01 17:31:14.104445 98.43% [INFO] mod_dialplan_xml.c:639 Processing 2004 <2004>->[dialled number] in context domain1.mydomain.com
2023-12-01 17:31:14.124447 98.43% [NOTICE] switch_cpp.cpp:1465 [xml_handler] multiple key:dialplan:domain1.mydomain.com
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->JBS] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (FAIL) [JBS] destination_number([dialled number]) =~ /^442037453988$/ break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->user_exists] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(user_exists=false)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [user_exists]=[false]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(from_user_exists=true)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [from_user_exists]=[true]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->caller-details] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(caller_destination=[dialled number])
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [caller_destination]=[[dialled number]]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(caller_id_name=2004)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [caller_id_name]=[2004]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->JBS_ext_dial] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (FAIL) [JBS_ext_dial] destination_number([dialled number]) =~ /^51(\d{3})$/ break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->global-variables] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(timezone=Europe/London) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(timezone=Europe/London)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [timezone]=[Europe/London]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->domain-variables] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action export(origination_callee_id_name=${caller_destination})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(operator=1000)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [operator]=[1000]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(record_name=${caller_id_number}-${destination_number}-${strftime(%Y)}${strftime(%b)}${strftime(%d)}-${strftime(%X)}.${record_ext}) INLINE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(record_name=2004-[dialled number]-2023Dec01-17:31:14.mp3)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [record_name]=[2004-[dialled number]-2023Dec01-17:31:14.mp3]
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 parsing [domain1.mydomain.com->simwood_UK] continue=false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (PASS) [simwood_UK] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Regex (PASS) [simwood_UK] destination_number([dialled number]) =~ /^(\(?(0|\+?44)[1-9]{1}\d{1,4}?\)?\s?\d{3,4}\s?\d{3,4})$/ break=on-false
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(sip_h_accountcode=${accountcode})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(sip_h_X-simwood-tag=${accountcode})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action export(call_direction=outbound)
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action unset(call_timeout)
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(inherit_codec=true)
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(ignore_display_updates=true)
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 Action set(callee_id_number=[dialled number])
Dialplan: sofia/internal/
2004@domain1.mydomain.com:5061 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/
2004@domain1.mydomain.com:5061 Action bridge(sofia/gateway/472ac2c1-90a3-4ae1-90f2-e084635129c8/[dialled number])
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/
2004@domain1.mydomain.com:5061) State Change CS_ROUTING -> CS_EXECUTE
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/
2004@domain1.mydomain.com:5061) State ROUTING going to sleep
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_EXECUTE (Cur 1 Tot 10971)
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/
2004@domain1.mydomain.com:5061) State EXECUTE
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_sofia.c:213 sofia/internal/
2004@domain1.mydomain.com:5061 SOFIA EXECUTE
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:323 sofia/internal/
2004@domain1.mydomain.com:5061 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(caller_id_number=2004)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [caller_id_number]=[2004]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(RFC2822_DATE=Fri, 01 Dec 2023 17:31:14 +0000)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [RFC2822_DATE]=[Fri, 01 Dec 2023 17:31:14 +0000]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 export(origination_callee_id_name=[dialled number])
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [origination_callee_id_name]=[[dialled number]]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(sip_h_accountcode=domain1.mydomain.com)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [sip_h_accountcode]=[domain1.mydomain.com]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(sip_h_X-simwood-tag=domain1.mydomain.com)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [sip_h_X-simwood-tag]=[domain1.mydomain.com]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 export(call_direction=outbound)
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[outbound]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 unset(call_timeout)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1818 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(hangup_after_bridge=true)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(effective_caller_id_name=Simplicity Communications)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [effective_caller_id_name]=[Simplicity Communications]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(effective_caller_id_number=[presented cli])
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [effective_caller_id_number]=[[presented cli]]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(inherit_codec=true)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(ignore_display_updates=true)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 set(callee_id_number=[dialled number])
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [callee_id_number]=[[dialled number]]
EXECUTE [depth=0] sofia/internal/
2004@domain1.mydomain.com:5061 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)
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_dptools.c:1673 SET sofia/internal/
2004@domain1.mydomain.com:5061 [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/
2004@domain1.mydomain.com:5061 bridge(sofia/gateway/472ac2c1-90a3-4ae1-90f2-e084635129c8/[dialled number])
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_channel.c:1269 sofia/internal/
2004@domain1.mydomain.com:5061 EXPORTING[export_vars] [domain_name]=[domain1.mydomain.com] to event
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_channel.c:1269 sofia/internal/
2004@domain1.mydomain.com:5061 EXPORTING[export_vars] [domain_uuid]=[db6ced60-5f38-4128-8d49-4ab32341252a] to event
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_channel.c:1269 sofia/internal/
2004@domain1.mydomain.com:5061 EXPORTING[export_vars] [origination_callee_id_name]=[[dialled number]] to event
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_channel.c:1269 sofia/internal/
2004@domain1.mydomain.com:5061 EXPORTING[export_vars] [call_direction]=[outbound] to event
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_ivr_originate.c:2291 Parsing global variables
2023-12-01 17:31:14.124447 98.43% [NOTICE] switch_channel.c:1123 New Channel sofia/external/[dialled number] [1f680310-f230-4516-b9b1-c3ed3714fd6e]
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_sofia.c:5117 (sofia/external/[dialled number]) State Change CS_NEW -> CS_INIT
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/external/[dialled number]) Running State Change CS_INIT (Cur 2 Tot 10972)
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:624 (sofia/external/[dialled number]) State INIT
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_sofia.c:97 sofia/external/[dialled number] SOFIA INIT
2023-12-01 17:31:14.124447 98.43% [INFO] sofia_glue.c:1654 sofia/external/[dialled number] sending invite call-id: (null)
2023-12-01 17:31:14.124447 98.43% [DEBUG] sofia_glue.c:1657 sofia/external/[dialled number] sending invite version: 1.10.9 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1701425882 1701425883 IN IP4 [external ip]
s=FreeSWITCH
c=IN IP4 [external ip]
t=0 0
m=audio 25992 RTP/AVP 0 8 9 123 101 102
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:123 opus/48000/2
a=fmtp:123 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:102 telephone-event/48000
a=fmtp:102 0-15
a=silenceSupp
ff - - - -
a=ptime:20
a=sendrecv
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:40 sofia/external/[dialled number] Standard INIT
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:48 (sofia/external/[dialled number]) State Change CS_INIT -> CS_ROUTING
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:624 (sofia/external/[dialled number]) State INIT going to sleep
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/external/[dialled number]) Running State Change CS_ROUTING (Cur 2 Tot 10972)
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:640 (sofia/external/[dialled number]) State ROUTING
2023-12-01 17:31:14.124447 98.43% [DEBUG] mod_sofia.c:158 sofia/external/[dialled number] SOFIA ROUTING
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_ivr_originate.c:67 (sofia/external/[dialled number]) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:640 (sofia/external/[dialled number]) State ROUTING going to sleep
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:581 (sofia/external/[dialled number]) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 10972)
2023-12-01 17:31:14.124447 98.43% [DEBUG] sofia.c:7487 Channel sofia/external/[dialled number] entering state [calling][0]
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:659 (sofia/external/[dialled number]) State CONSUME_MEDIA
2023-12-01 17:31:14.124447 98.43% [DEBUG] switch_core_state_machine.c:659 (sofia/external/[dialled number]) State CONSUME_MEDIA going to sleep
2023-12-01 17:31:14.564509 98.33% [DEBUG] sofia.c:7487 Channel sofia/external/[dialled number] entering state [proceeding][183]
2023-12-01 17:31:14.564509 98.33% [DEBUG] sofia.c:7497 Remote SDP:
v=0
o=Sonus_UAC 398912 122132 IN IP4 185.63.140.49
s=SIP Media Capabilities
c=IN IP4 185.63.140.49
t=0 0
m=audio 48238 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:48239
a=ptime:20
2023-12-01 17:31:14.564509 98.33% [NOTICE] sofia.c:7500 Pre-Answer sofia/external/[dialled number]!
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_channel.c:3566 (sofia/external/[dialled number]) Callstate Change DOWN -> EARLY
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5582 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:2]
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5443 Set telephone-event payload to 101@8000
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:3750 Set Codec sofia/external/[dialled number] PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_codec.c:111 sofia/external/[dialled number] Original read codec set to PCMA:8
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5792 Set telephone-event payload to 101@8000
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:5850 sofia/external/[dialled number] Set 2833 dtmf send payload to 101 recv payload to 101
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:8651 AUDIO RTP [sofia/external/[dialled number]] [internal ip] port 25992 -> 185.63.140.49 port 48238 codec: 8 ms: 20
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_rtp.c:4377 Starting timer [soft] 160 bytes per 20ms
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_core_media.c:8871 Activating RTCP PORT 48239
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_rtp.c:4708 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 48239
2023-12-01 17:31:14.564509 98.33% [DEBUG] switch_rtp.c:2534 Setting RTCP remote addr to 185.63.140.49:48239 2
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8963 sofia/external/[dialled number] Set 2833 dtmf send payload to 101
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8970 sofia/external/[dialled number] Set 2833 dtmf receive payload to 101
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8993 sofia/external/[dialled number] Set rtp dtmf delay to 40
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_ivr_originate.c:448 Setting codec string on sofia/internal/
2004@domain1.mydomain.com:5061 to PCMA@8000h@20i
2023-12-01 17:31:14.584457 98.33% [INFO] switch_ivr_originate.c:3851 Sending early media
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5582 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5527 Audio Codec Compare [opus:123:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5443 Set telephone-event payload to 101@8000
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:3750 Set Codec sofia/internal/
2004@domain1.mydomain.com:5061 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_codec.c:111 sofia/internal/
2004@domain1.mydomain.com:5061 Original read codec set to PCMA:8
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5792 Set telephone-event payload to 101@8000
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:5850 sofia/internal/
2004@domain1.mydomain.com:5061 Set 2833 dtmf send payload to 101 recv payload to 101
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8651 AUDIO RTP [sofia/internal/
2004@domain1.mydomain.com:5061] [internal ip] port 25806 -> 192.168.87.14 port 13670 codec: 8 ms: 20
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_rtp.c:4377 Starting timer [soft] 160 bytes per 20ms
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8963 sofia/internal/
2004@domain1.mydomain.com:5061 Set 2833 dtmf send payload to 101
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8970 sofia/internal/
2004@domain1.mydomain.com:5061 Set 2833 dtmf receive payload to 101
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8993 sofia/internal/
2004@domain1.mydomain.com:5061 Set rtp dtmf delay to 40
2023-12-01 17:31:14.584457 98.33% [NOTICE] sofia_media.c:90 Pre-Answer sofia/internal/
2004@domain1.mydomain.com:5061!
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_channel.c:3566 (sofia/internal/
2004@domain1.mydomain.com:5061) Callstate Change RINGING -> EARLY
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_media.c:8633 Audio params are unchanged for sofia/internal/
2004@domain1.mydomain.com:5061.
2023-12-01 17:31:14.584457 98.33% [DEBUG] mod_sofia.c:2609 Ring SDP:
v=0
o=FreeSWITCH 1701426068 1701426069 IN IP4 [external ip]
s=FreeSWITCH
c=IN IP4 [external ip]
t=0 0
m=audio 25806 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_ivr_originate.c:3902 Originate Resulted in Success: [sofia/external/[dialled number]] Peer UUID: 1f680310-f230-4516-b9b1-c3ed3714fd6e
2023-12-01 17:31:14.584457 98.33% [DEBUG] sofia.c:7487 Channel sofia/internal/
2004@domain1.mydomain.com:5061 entering state [early][183]
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_ivr_bridge.c:1791 (sofia/external/[dialled number]) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/[dialled number]) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 10972)
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_core_state_machine.c:650 (sofia/external/[dialled number]) State EXCHANGE_MEDIA
2023-12-01 17:31:14.584457 98.33% [DEBUG] mod_sofia.c:671 SOFIA EXCHANGE_MEDIA
2023-12-01 17:31:14.584457 98.33% [DEBUG] switch_rtp.c:1775 rtcp_stats_init: audio ssrc[1080729933] base_seq[3]
2023-12-01 17:31:14.624453 98.33% [DEBUG] switch_rtp.c:7511 Correct audio ip/port confirmed.
2023-12-01 17:31:15.064502 98.33% [INFO] switch_rtp.c:7471 Auto Changing audio port from 192.168.87.14:13670 to [provider ip]:48230
2023-12-01 17:31:21.564460 98.37% [INFO] sofia.c:1348 sofia/external/[dialled number] Update Callee ID to "[dialled number]" <[dialled number]>
2023-12-01 17:31:21.564460 98.37% [DEBUG] sofia.c:7487 Channel sofia/external/[dialled number] entering state [completing][200]
2023-12-01 17:31:21.564460 98.37% [DEBUG] sofia.c:7494 Duplicate SDP
v=0
o=Sonus_UAC 398912 122132 IN IP4 185.63.140.49
s=SIP Media Capabilities
c=IN IP4 185.63.140.49
t=0 0
m=audio 48238 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:48239
a=ptime:20
2023-12-01 17:31:21.584448 98.37% [DEBUG] sofia.c:7487 Channel sofia/external/[dialled number] entering state [ready][200]
2023-12-01 17:31:21.584448 98.37% [NOTICE] sofia.c:8616 Channel [sofia/external/[dialled number]] has been answered
2023-12-01 17:31:21.584448 98.37% [DEBUG] switch_channel.c:3893 (sofia/external/[dialled number]) Callstate Change EARLY -> ACTIVE
2023-12-01 17:31:21.604476 98.37% [DEBUG] switch_core_media.c:8633 Audio params are unchanged for sofia/internal/
2004@domain1.mydomain.com:5061.
2023-12-01 17:31:21.604476 98.37% [DEBUG] mod_sofia.c:913 Local SDP sofia/internal/
2004@domain1.mydomain.com:5061:
v=0
o=FreeSWITCH 1701426068 1701426070 IN IP4 [external ip]
s=FreeSWITCH
c=IN IP4 [external ip]
t=0 0
m=audio 25806 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
2023-12-01 17:31:21.604476 98.37% [NOTICE] switch_ivr_bridge.c:730 Channel [sofia/internal/
2004@domain1.mydomain.com:5061] has been answered
2023-12-01 17:31:21.604476 98.37% [DEBUG] switch_channel.c:3893 (sofia/internal/
2004@domain1.mydomain.com:5061) Callstate Change EARLY -> ACTIVE
2023-12-01 17:31:21.604476 98.37% [DEBUG] sofia.c:7487 Channel sofia/internal/
2004@domain1.mydomain.com:5061 entering state [completed][200]
2023-12-01 17:31:21.644466 98.37% [DEBUG] switch_rtp.c:7511 Correct audio ip/port confirmed.
2023-12-01 17:31:21.644466 98.37% [DEBUG] switch_rtp.c:7511 Correct audio ip/port confirmed.
2023-12-01 17:31:21.664486 98.37% [DEBUG] sofia.c:7487 Channel sofia/internal/
2004@domain1.mydomain.com:5061 entering state [ready][200]
2023-12-01 17:31:24.764452 98.23% [NOTICE] sofia.c:1065 Hangup sofia/internal/
2004@domain1.mydomain.com:5061 [CS_EXECUTE] [NORMAL_CLEARING]
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/internal/
2004@domain1.mydomain.com:5061]
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_ivr_bridge.c:819 sofia/internal/
2004@domain1.mydomain.com:5061 ending bridge by request from write function
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/external/[dialled number]]
2023-12-01 17:31:24.764452 98.23% [NOTICE] switch_ivr_bridge.c:1027 Hangup sofia/external/[dialled number] [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:650 (sofia/external/[dialled number]) State EXCHANGE_MEDIA going to sleep
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:581 (sofia/external/[dialled number]) Running State Change CS_HANGUP (Cur 2 Tot 10972)
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:844 (sofia/external/[dialled number]) Callstate Change ACTIVE -> HANGUP
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:846 (sofia/external/[dialled number]) State HANGUP
2023-12-01 17:31:24.764452 98.23% [DEBUG] mod_sofia.c:462 sofia/external/[dialled number] Overriding SIP cause 480 with 200 from the other leg
2023-12-01 17:31:24.764452 98.23% [DEBUG] mod_sofia.c:468 Channel sofia/external/[dialled number] hanging up, cause: NORMAL_CLEARING
2023-12-01 17:31:24.764452 98.23% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/external/[dialled number]
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:59 sofia/external/[dialled number] Standard HANGUP, cause: NORMAL_CLEARING
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:846 (sofia/external/[dialled number]) State HANGUP going to sleep
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:616 (sofia/external/[dialled number]) State Change CS_HANGUP -> CS_REPORTING
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:581 (sofia/external/[dialled number]) Running State Change CS_REPORTING (Cur 2 Tot 10972)
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:932 (sofia/external/[dialled number]) State REPORTING
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:168 sofia/external/[dialled number] Standard REPORTING, cause: NORMAL_CLEARING
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:932 (sofia/external/[dialled number]) State REPORTING going to sleep
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_state_machine.c:607 (sofia/external/[dialled number]) State Change CS_REPORTING -> CS_DESTROY
2023-12-01 17:31:24.764452 98.23% [DEBUG] switch_core_session.c:1743 Session 10972 (sofia/external/[dialled number]) Locked, Waiting on external entities
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_ivr_bridge.c:1893 sofia/internal/
2004@domain1.mydomain.com:5061 skip receive message [UNBRIDGE] (channel is hungup already)
2023-12-01 17:31:24.784444 98.23% [NOTICE] switch_core_session.c:1761 Session 10972 (sofia/external/[dialled number]) Ended
2023-12-01 17:31:24.784444 98.23% [NOTICE] switch_core_session.c:1765 Close Channel sofia/external/[dialled number] [CS_DESTROY]
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_session.c:2973 sofia/internal/
2004@domain1.mydomain.com:5061 skip receive message [PHONE_EVENT] (channel is hungup already)
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/
2004@domain1.mydomain.com:5061) State EXECUTE going to sleep
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_HANGUP (Cur 1 Tot 10972)
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/
2004@domain1.mydomain.com:5061) Callstate Change ACTIVE -> HANGUP
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:735 (sofia/external/[dialled number]) Running State Change CS_DESTROY (Cur 1 Tot 10972)
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:745 (sofia/external/[dialled number]) State DESTROY
2023-12-01 17:31:24.784444 98.23% [DEBUG] mod_sofia.c:379 sofia/external/[dialled number] SOFIA DESTROY
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:175 sofia/external/[dialled number] Standard DESTROY
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:745 (sofia/external/[dialled number]) State DESTROY going to sleep
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/
2004@domain1.mydomain.com:5061) State HANGUP
2023-12-01 17:31:24.784444 98.23% [DEBUG] mod_sofia.c:468 Channel sofia/internal/
2004@domain1.mydomain.com:5061 hanging up, cause: NORMAL_CLEARING
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:59 sofia/internal/
2004@domain1.mydomain.com:5061 Standard HANGUP, cause: NORMAL_CLEARING
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/
2004@domain1.mydomain.com:5061) State HANGUP going to sleep
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/
2004@domain1.mydomain.com:5061) State Change CS_HANGUP -> CS_REPORTING
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_REPORTING (Cur 1 Tot 10972)
2023-12-01 17:31:24.784444 98.23% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/
2004@domain1.mydomain.com:5061) State REPORTING
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:168 sofia/internal/
2004@domain1.mydomain.com:5061 Standard REPORTING, cause: NORMAL_CLEARING
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/
2004@domain1.mydomain.com:5061) State REPORTING going to sleep
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/
2004@domain1.mydomain.com:5061) State Change CS_REPORTING -> CS_DESTROY
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_session.c:1743 Session 10971 (sofia/internal/
2004@domain1.mydomain.com:5061) Locked, Waiting on external entities
2023-12-01 17:31:24.844484 98.23% [NOTICE] switch_core_session.c:1761 Session 10971 (sofia/internal/
2004@domain1.mydomain.com:5061) Ended
2023-12-01 17:31:24.844484 98.23% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal/
2004@domain1.mydomain.com:5061 [CS_DESTROY]
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/
2004@domain1.mydomain.com:5061) Running State Change CS_DESTROY (Cur 0 Tot 10972)
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/
2004@domain1.mydomain.com:5061) State DESTROY
2023-12-01 17:31:24.844484 98.23% [DEBUG] mod_sofia.c:379 sofia/internal/
2004@domain1.mydomain.com:5061 SOFIA DESTROY
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:175 sofia/internal/
2004@domain1.mydomain.com:5061 Standard DESTROY
2023-12-01 17:31:24.844484 98.23% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/
2004@domain1.mydomain.com:5061) State DESTROY going to sleep
freeswitch@i-08417e0a63f511bc4>