CallerID replaced with Gateway Username when sending calls from SIP to FusionPBX

[SwaggerRO19]

Hi all!

I'm having a hard time solving an issue with the CallerID that's been bothering since 2 days ago. I tried to find an answer on PBXForums and on Google, but no success.

I'm using FREESWITCH (FusionPBX) latest version as a Gateway for my 3CX PBX. On FreeSwitch I have all the Carriers for the outbound calling.

Inbound & outbound calling works just fine, but I have an issue that causes me troubles sending outbound calls through Carriers.

So my network looks something like:

3CX PBX - connected to FusionPBX via extension - outbound to Carrier.

3CX is sending in the INVITE for an outbound call the CallerID 15051001000, FusionPBX it's accordingly receiving it, but it's not taking this to the INVITE that's sending to the Carrier for the outbound call, but instead it's sending the username of the Gateway SIP Trunk registration, which causes me the call to be sent with the CallerID.... of the username of Gateway SIP Trunk.

Here's the latest log from fs_cli:

2022-12-07 06:17:00.314782 87.77% [NOTICE] sofia_reg.c:463 Registering 1f80b26e-5530-4e0a-b781-3dd262b0b545
2022-12-07 06:17:23.534793 91.80% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [1a6e8bd0-4b59-40a1-b9d8-8410e564b136]
2022-12-07 06:17:23.534793 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_NEW (Cur 1 Tot 1)
2022-12-07 06:17:23.534793 91.80% [INFO] sofia.c:10468 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 receiving invite from 3CXPBXIP:5060 version: 1.10.8 -release 64bit call-id: 7g_rvEeGAxaHE4RRhaXCdg..
2022-12-07 06:17:23.534793 91.80% [DEBUG] sofia.c:10562 verifying acl "providers" for ip/port 3CXPBXIP:0.
2022-12-07 06:17:23.534793 91.80% [DEBUG] sofia.c:2419 detaching session 1a6e8bd0-4b59-40a1-b9d8-8410e564b136
2022-12-07 06:17:23.534793 91.80% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State NEW
2022-12-07 06:17:23.594792 91.80% [DEBUG] sofia.c:2532 Re-attaching to session 1a6e8bd0-4b59-40a1-b9d8-8410e564b136
2022-12-07 06:17:23.614790 91.80% [INFO] sofia.c:10468 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 receiving invite from 3CXPBXIP:5060 version: 1.10.8 -release 64bit call-id: 7g_rvEeGAxaHE4RRhaXCdg..
2022-12-07 06:17:23.614790 91.80% [DEBUG] sofia.c:10562 verifying acl "providers" for ip/port 3CXPBXIP:0.
2022-12-07 06:17:23.634793 91.80% [DEBUG] sofia.c:7502 Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 entering state [received][100]
2022-12-07 06:17:23.634793 91.80% [DEBUG] sofia.c:7512 Remote SDP:
v=0
o=3cxPS 10989308542451712 12682446961115137 IN IP4 3CXPBXIP
s=3cxPS Audio call
c=IN IP4 3CXPBXIP
t=0 0
m=audio 9310 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000

2022-12-07 06:17:23.634793 91.80% [DEBUG] sofia.c:7915 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State Change CS_NEW -> CS_INIT
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_INIT (Cur 1 Tot 1)
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State INIT
2022-12-07 06:17:23.634793 91.80% [DEBUG] mod_sofia.c:97 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 SOFIA INIT
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:40 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Standard INIT
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State Change CS_INIT -> CS_ROUTING
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State INIT going to sleep
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_ROUTING (Cur 1 Tot 1)
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_channel.c:2380 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Callstate Change DOWN -> RINGING
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State ROUTING
2022-12-07 06:17:23.634793 91.80% [DEBUG] mod_sofia.c:158 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 SOFIA ROUTING
2022-12-07 06:17:23.634793 91.80% [DEBUG] switch_core_state_machine.c:230 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Standard ROUTING
2022-12-07 06:17:23.634793 91.80% [INFO] mod_dialplan_xml.c:639 Processing 15051001000 <15051001000>->16417930191 in context FreeSWITCHPBXIP
2022-12-07 06:17:23.634793 91.80% [NOTICE] switch_cpp.cpp:1465 [xml_handler] multiple key:dialplan:FreeSWITCHPBXIP
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->user_exists] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(user_exists=false)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [user_exists]=[false]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(from_user_exists=false)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [from_user_exists]=[false]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->caller-details] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(caller_destination=16417930191)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [caller_destination]=[16417930191]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(caller_id_name=57914385)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [caller_id_name]=[57914385]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->caller-details] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [caller-details] ${caller_destination}(16417930191) =~ /^$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->global-variables] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->domain-variables] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(operator=1000)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [operator]=[1000]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->call-direction] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 export(call_direction=local)
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->is_loopback] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->user_record] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->rtp_has_crypto] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 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/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->redial] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [redial] destination_number(16417930191) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->speed_dial] continue=false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [speed_dial] destination_number(16417930191) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->default_caller_id] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [default_caller_id] ${call_direction}(local) =~ /outbound/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->user_hold_music] continue=true
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 parsing [FreeSWITCHPBXIP->SIP.US.129d229d2d4] continue=false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [SIP.US.129d229d2d4] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Regex (PASS) [SIP.US.129d229d2d4] destination_number(16417930191) =~ /^\+?1?([2-9]\d{2}[2-9]\d{2}\d{4})$/ break=on-false
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 export(call_direction=outbound)
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action unset(call_timeout)
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(inherit_codec=true)
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(ignore_display_updates=true)
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(callee_id_number=6417930191)
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 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/15051001000@FreeSWITCHPBXIP:5060 Action bridge(sofia/gateway/1f80b26e-5530-4e0a-b781-3dd262b0b545/16417930191)
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State Change CS_ROUTING -> CS_EXECUTE
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State ROUTING going to sleep
2022-12-07 06:17:23.654786 91.80% [CONSOLE] sofia_presence.c:1620 Event Thread Started
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State EXECUTE
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_sofia.c:213 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 SOFIA EXECUTE
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_core_state_machine.c:323 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(caller_id_number=57914385)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [caller_id_number]=[57914385]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(RFC2822_DATE=Wed, 07 Dec 2022 06:17:23 -0500)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [RFC2822_DATE]=[Wed, 07 Dec 2022 06:17:23 -0500]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 export(origination_callee_id_name=16417930191)
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [origination_callee_id_name]=[16417930191]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 hash(insert/FreeSWITCHPBXIP-last_dial/57914385/16417930191)
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 unset(call_timeout)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1818 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(hangup_after_bridge=true)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(effective_caller_id_name=)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [effective_caller_id_name]=[UNDEF]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(effective_caller_id_number=)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [effective_caller_id_number]=[UNDEF]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(inherit_codec=true)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(ignore_display_updates=true)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 set(callee_id_number=6417930191)
2022-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [callee_id_number]=[6417930191]
EXECUTE [depth=0] sofia/internal/15051001000@FreeSWITCHPBXIP:5060 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-12-07 06:17:23.654786 91.80% [DEBUG] mod_dptools.c:1673 SET sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [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/15051001000@FreeSWITCHPBXIP:5060 bridge(sofia/gateway/1f80b26e-5530-4e0a-b781-3dd262b0b545/16417930191)
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1269 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 EXPORTING[export_vars] [domain_name]=[FreeSWITCHPBXIP] to event
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1269 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 EXPORTING[export_vars] [domain_uuid]=[67fd3ea6-8200-4280-a045-bdddfb714ac3] to event
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1269 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1269 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_channel.c:1269 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 EXPORTING[export_vars] [origination_callee_id_name]=[16417930191] to event
2022-12-07 06:17:23.654786 91.80% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-12-07 06:17:23.674788 91.80% [NOTICE] switch_channel.c:1123 New Channel sofia/external/16417930191 [18c04320-3b9a-4728-9dd4-af256ce6c6a0]
2022-12-07 06:17:23.674788 91.80% [DEBUG] mod_sofia.c:5105 sofia/external/16417930191 setting variable [sip_cid_type]=[pid]
2022-12-07 06:17:23.674788 91.80% [DEBUG] mod_sofia.c:5121 (sofia/external/16417930191) State Change CS_NEW -> CS_INIT
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/external/16417930191) Running State Change CS_INIT (Cur 2 Tot 2)
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:624 (sofia/external/16417930191) State INIT
2022-12-07 06:17:23.674788 91.80% [DEBUG] mod_sofia.c:97 sofia/external/16417930191 SOFIA INIT
2022-12-07 06:17:23.674788 91.80% [INFO] sofia_glue.c:1654 sofia/external/16417930191 sending invite call-id: (null)
2022-12-07 06:17:23.674788 91.80% [DEBUG] sofia_glue.c:1657 sofia/external/16417930191 sending invite version: 1.10.8 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1670388747 1670388748 IN IP4 FreeSWITCHPBXIP
s=FreeSWITCH
c=IN IP4 FreeSWITCHPBXIP
t=0 0
m=audio 23096 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:40 sofia/external/16417930191 Standard INIT
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:48 (sofia/external/16417930191) State Change CS_INIT -> CS_ROUTING
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:624 (sofia/external/16417930191) State INIT going to sleep
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/external/16417930191) Running State Change CS_ROUTING (Cur 2 Tot 2)
2022-12-07 06:17:23.674788 91.80% [DEBUG] sofia.c:7502 Channel sofia/external/16417930191 entering state [calling][0]
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:640 (sofia/external/16417930191) State ROUTING
2022-12-07 06:17:23.674788 91.80% [DEBUG] mod_sofia.c:158 sofia/external/16417930191 SOFIA ROUTING
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_ivr_originate.c:67 (sofia/external/16417930191) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:640 (sofia/external/16417930191) State ROUTING going to sleep
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:581 (sofia/external/16417930191) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2)
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:659 (sofia/external/16417930191) State CONSUME_MEDIA
2022-12-07 06:17:23.674788 91.80% [DEBUG] switch_core_state_machine.c:659 (sofia/external/16417930191) State CONSUME_MEDIA going to sleep
2022-12-07 06:17:23.934782 91.80% [DEBUG] sofia.c:7502 Channel sofia/external/16417930191 entering state [calling][0]
2022-12-07 06:17:27.014787 92.73% [DEBUG] sofia.c:7502 Channel sofia/external/16417930191 entering state [proceeding][183]
2022-12-07 06:17:27.014787 92.73% [DEBUG] sofia.c:7512 Remote SDP:
v=0
o=Sonus_UAC 389772 43278 IN IP4 67.231.1.170
s=SIP Media Capabilities
c=IN IP4 67.231.0.3
t=0 0
m=audio 13012 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2022-12-07 06:17:27.014787 92.73% [NOTICE] sofia.c:7515 Pre-Answer sofia/external/16417930191!
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_channel.c:3622 (sofia/external/16417930191) Callstate Change DOWN -> EARLY
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5579 Set telephone-event payload to 101@8000
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:3883 Set Codec sofia/external/16417930191 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_codec.c:111 sofia/external/16417930191 Original read codec set to PCMU:0
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5928 Set telephone-event payload to 101@8000
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5986 sofia/external/16417930191 Set 2833 dtmf send payload to 101 recv payload to 101
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:8787 AUDIO RTP [sofia/external/16417930191] FreeSWITCHPBXIP port 23096 -> 67.231.0.3 port 13012 codec: 0 ms: 20
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:9099 sofia/external/16417930191 Set 2833 dtmf send payload to 101
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:9106 sofia/external/16417930191 Set 2833 dtmf receive payload to 101
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:9129 sofia/external/16417930191 Set rtp dtmf delay to 40
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_ivr_originate.c:448 Setting codec string on sofia/internal/15051001000@FreeSWITCHPBXIP:5060 to PCMU@8000h@20i
2022-12-07 06:17:27.014787 92.73% [INFO] switch_ivr_originate.c:3841 Sending early media
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5579 Set telephone-event payload to 101@8000
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:3883 Set Codec sofia/internal/15051001000@FreeSWITCHPBXIP:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_codec.c:111 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Original read codec set to PCMU:0
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5928 Set telephone-event payload to 101@8000
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:5986 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:8787 AUDIO RTP [sofia/internal/15051001000@FreeSWITCHPBXIP:5060] FreeSWITCHPBXIP port 17660 -> 3CXPBXIP port 9310 codec: 0 ms: 20
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:9099 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Set 2833 dtmf send payload to 101
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:9106 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Set 2833 dtmf receive payload to 101
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:9129 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Set rtp dtmf delay to 40
2022-12-07 06:17:27.014787 92.73% [NOTICE] sofia_media.c:90 Pre-Answer sofia/internal/15051001000@FreeSWITCHPBXIP:5060!
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_channel.c:3622 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Callstate Change RINGING -> EARLY
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_media.c:8769 Audio params are unchanged for sofia/internal/15051001000@FreeSWITCHPBXIP:5060.
2022-12-07 06:17:27.014787 92.73% [DEBUG] mod_sofia.c:2611 Ring SDP:
v=0
o=FreeSWITCH 1670394187 1670394188 IN IP4 FreeSWITCHPBXIP
s=FreeSWITCH
c=IN IP4 FreeSWITCHPBXIP
t=0 0
m=audio 17660 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

2022-12-07 06:17:27.014787 92.73% [DEBUG] sofia.c:7502 Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 entering state [early][183]
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_ivr_originate.c:3892 Originate Resulted in Success: [sofia/external/16417930191] Peer UUID: 18c04320-3b9a-4728-9dd4-af256ce6c6a0
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_ivr_bridge.c:1791 (sofia/external/16417930191) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/16417930191) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 2)
2022-12-07 06:17:27.014787 92.73% [DEBUG] switch_core_state_machine.c:650 (sofia/external/16417930191) State EXCHANGE_MEDIA
2022-12-07 06:17:27.014787 92.73% [DEBUG] mod_sofia.c:671 SOFIA EXCHANGE_MEDIA
2022-12-07 06:17:27.054787 92.73% [DEBUG] sofia.c:7502 Channel sofia/external/16417930191 entering state [completing][200]
2022-12-07 06:17:27.054787 92.73% [DEBUG] sofia.c:7509 Duplicate SDP
v=0
o=Sonus_UAC 389772 43278 IN IP4 67.231.1.170
s=SIP Media Capabilities
c=IN IP4 67.231.0.3
t=0 0
m=audio 13012 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2022-12-07 06:17:27.054787 92.73% [DEBUG] sofia.c:7502 Channel sofia/external/16417930191 entering state [ready][200]
2022-12-07 06:17:27.054787 92.73% [NOTICE] sofia.c:8631 Channel [sofia/external/16417930191] has been answered
2022-12-07 06:17:27.054787 92.73% [DEBUG] switch_channel.c:3950 (sofia/external/16417930191) Callstate Change EARLY -> ACTIVE
2022-12-07 06:17:27.054787 92.73% [DEBUG] switch_core_media.c:8769 Audio params are unchanged for sofia/internal/15051001000@FreeSWITCHPBXIP:5060.
2022-12-07 06:17:27.054787 92.73% [DEBUG] mod_sofia.c:913 Local SDP sofia/internal/15051001000@FreeSWITCHPBXIP:5060:
v=0
o=FreeSWITCH 1670394187 1670394189 IN IP4 FreeSWITCHPBXIP
s=FreeSWITCH
c=IN IP4 FreeSWITCHPBXIP
t=0 0
m=audio 17660 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

2022-12-07 06:17:27.054787 92.73% [DEBUG] sofia.c:7502 Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 entering state [completed][200]
2022-12-07 06:17:27.054787 92.73% [NOTICE] switch_ivr_bridge.c:730 Channel [sofia/internal/15051001000@FreeSWITCHPBXIP:5060] has been answered
2022-12-07 06:17:27.054787 92.73% [DEBUG] switch_channel.c:3950 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Callstate Change EARLY -> ACTIVE
2022-12-07 06:17:27.114791 93.23% [DEBUG] switch_rtp.c:7925 Correct audio ip/port confirmed.
2022-12-07 06:17:27.134783 93.23% [DEBUG] sofia.c:7502 Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 entering state [ready][200]
2022-12-07 06:17:30.994790 93.77% [DEBUG] switch_rtp.c:7925 Correct audio ip/port confirmed.
2022-12-07 06:17:36.754794 94.03% [NOTICE] sofia.c:1065 Hangup sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2022-12-07 06:17:36.754794 94.03% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/internal/15051001000@FreeSWITCHPBXIP:5060]
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_ivr_bridge.c:819 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 ending bridge by request from write function
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/external/16417930191]
2022-12-07 06:17:36.774784 94.03% [NOTICE] switch_ivr_bridge.c:1027 Hangup sofia/external/16417930191 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:650 (sofia/external/16417930191) State EXCHANGE_MEDIA going to sleep
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:581 (sofia/external/16417930191) Running State Change CS_HANGUP (Cur 2 Tot 2)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:844 (sofia/external/16417930191) Callstate Change ACTIVE -> HANGUP
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:846 (sofia/external/16417930191) State HANGUP
2022-12-07 06:17:36.774784 94.03% [DEBUG] mod_sofia.c:462 sofia/external/16417930191 Overriding SIP cause 480 with 200 from the other leg
2022-12-07 06:17:36.774784 94.03% [DEBUG] mod_sofia.c:468 Channel sofia/external/16417930191 hanging up, cause: NORMAL_CLEARING
2022-12-07 06:17:36.774784 94.03% [DEBUG] mod_sofia.c:522 Sending BYE to sofia/external/16417930191
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:59 sofia/external/16417930191 Standard HANGUP, cause: NORMAL_CLEARING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:846 (sofia/external/16417930191) State HANGUP going to sleep
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:616 (sofia/external/16417930191) State Change CS_HANGUP -> CS_REPORTING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:581 (sofia/external/16417930191) Running State Change CS_REPORTING (Cur 2 Tot 2)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:932 (sofia/external/16417930191) State REPORTING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:168 sofia/external/16417930191 Standard REPORTING, cause: NORMAL_CLEARING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:932 (sofia/external/16417930191) State REPORTING going to sleep
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:607 (sofia/external/16417930191) State Change CS_REPORTING -> CS_DESTROY
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_session.c:1747 Session 2 (sofia/external/16417930191) Locked, Waiting on external entities
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_ivr_bridge.c:1893 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 skip receive message [UNBRIDGE] (channel is hungup already)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_session.c:2977 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 skip receive message [PHONE_EVENT] (channel is hungup already)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State EXECUTE going to sleep
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_HANGUP (Cur 2 Tot 2)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Callstate Change ACTIVE -> HANGUP
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State HANGUP
2022-12-07 06:17:36.774784 94.03% [DEBUG] mod_sofia.c:468 Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 hanging up, cause: NORMAL_CLEARING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:59 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Standard HANGUP, cause: NORMAL_CLEARING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State HANGUP going to sleep
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State Change CS_HANGUP -> CS_REPORTING
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_REPORTING (Cur 2 Tot 2)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State REPORTING
2022-12-07 06:17:36.774784 94.03% [NOTICE] switch_core_session.c:1765 Session 2 (sofia/external/16417930191) Ended
2022-12-07 06:17:36.774784 94.03% [NOTICE] switch_core_session.c:1769 Close Channel sofia/external/16417930191 [CS_DESTROY]
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:735 (sofia/external/16417930191) Running State Change CS_DESTROY (Cur 1 Tot 2)
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:745 (sofia/external/16417930191) State DESTROY
2022-12-07 06:17:36.774784 94.03% [DEBUG] mod_sofia.c:379 sofia/external/16417930191 SOFIA DESTROY
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:175 sofia/external/16417930191 Standard DESTROY
2022-12-07 06:17:36.774784 94.03% [DEBUG] switch_core_state_machine.c:745 (sofia/external/16417930191) State DESTROY going to sleep
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:168 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Standard REPORTING, cause: NORMAL_CLEARING
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State REPORTING going to sleep
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State Change CS_REPORTING -> CS_DESTROY
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_session.c:1747 Session 1 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Locked, Waiting on external entities
2022-12-07 06:17:36.914788 94.03% [NOTICE] switch_core_session.c:1765 Session 1 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Ended
2022-12-07 06:17:36.914788 94.03% [NOTICE] switch_core_session.c:1769 Close Channel sofia/internal/15051001000@FreeSWITCHPBXIP:5060 [CS_DESTROY]
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) Running State Change CS_DESTROY (Cur 0 Tot 2)
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State DESTROY
2022-12-07 06:17:36.914788 94.03% [DEBUG] mod_sofia.c:379 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 SOFIA DESTROY
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:175 sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Standard DESTROY
2022-12-07 06:17:36.914788 94.03% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/15051001000@FreeSWITCHPBXIP:5060) State DESTROY going to sleep

I've bolded the line where I can see that FreeSwitch it's setting the CallerID to 57914385 instead of sending the CLID of the originating DID 15051001000.

I'm sending from the 3CX PBX the CallerID (the originating DID) in the FROM, RPID, PAID, PAI, but FreeSwitch feels like it needs to be adjusted with the SIP Trunk username....

Any ideeas?

Thank you!

 

[SwaggerRO19]

And here's the Call Ladder from Dashboard -> Recent Calls - View all - the latest problematic call:

Call Details   
A detailed view of the call and all information regarding it. The information contains caller id name and number, channel data, Call variables, call flow, timing information, and other useful call details.


Summary     
Direction    Name    Number    Destination    Start    End    Duration    Status
outbound    15051001000    15051001000    16417930191    2022-12-07 06:17:23    2022-12-07 06:17:36    0:00:13    NORMAL_CLEARING


Call Flow Summary     
Destination    Start    End    Duration
16417930191    2022-12-07 13:17:23    2022-12-07 13:17:36    0:00:13


Call Stats: Audio: inbound     
Name    Value
mos    4.50
raw_bytes    83076
flaw_total    0
media_bytes    83076
packet_count    483
mean_interval    20.00
largest_jb_size    0
cng_packet_count    0
jitter_loss_rate    0.00
dtmf_packet_count    0
jitter_burst_rate    0.00
skip_packet_count    5
flush_packet_count    0
media_packet_count    483
quality_percentage    100.00
jitter_max_variance    0.00
jitter_min_variance    0.00
jitter_packet_count    0


Call Stats: Audio: outbound     
Name    Value
raw_bytes    49020
media_bytes    49020
packet_count    285
cng_packet_count    0
rtcp_octet_count    0
dtmf_packet_count    0
rtcp_packet_count    0
skip_packet_count    0
media_packet_count    285




Channel Data     
Name    Value
caps     1=1;2=1;3=1;4=1;5=1;6=1;8=1;9=1;10=1
flags     0=1;1=1;3=1;39=1;40=1;42=1;45=1;50=1;55=1;78=1;110=1;116=1;117=1;126=1;163= 1;168=1;169=1
state     CS_REPORTING
direction     inbound
state_number     11


Variables     
Name    Value
uuid    1a6e8bd0-4b59-40a1-b9d8-8410e564b136
billsec    9
waitsec    4
DP_MATCH    164179301916417930191
billmsec    9720
billusec    9719997
duration    13
last_app    bridge
last_arg    sofia/gateway/1f80b26e-5530-4e0a-b781-3dd262b0b545/16417930191
operator    1000
sip_cseq    2
waitmsec    3400
waitusec    3399997
Core-UUID    ac743fee-6626-4e1c-9352-9484d62f35e7
answersec    4
call_uuid    1a6e8bd0-4b59-40a1-b9d8-8410e564b136
caller_id    "15051001000" <15051001000>
direction    inbound
dtmf_type    rfc2833
end_epoch    1670411856
end_stamp    2022-12-07 06:17:36
limit_max    5
mduration    13160
read_rate    8000
sip_allow    INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE, UPDATE
uduration    13159994
user_name    57914385 -> instead, this is the username that I'm authenticating with to the Carrier - SIP Trunk
DIALSTATUS    SUCCESS
Event-Name    REQUEST_PARAMS
answermsec    3440
answerusec    3439997
end_uepoch    1670411856774784
read_codec    PCMU
rtp_use_pt    0
session_id    1
sip_to_tag    B69yrXNmcQv8m
sip_to_uri    16417930191@FREESWITCHIP:5060
write_rate    8000
accountcode    FREESWITCHIP
bridge_uuid    18c04320-3b9a-4728-9dd4-af256ce6c6a0
domain_name    FREESWITCHIP
domain_uuid    67fd3ea6-8200-4280-a045-bdddfb714ac3
export_vars    domain_name,domain_uuid,call_direction,call_direction,origination_callee_id _name
presence_id    57914385@FREESWITCHIP
progresssec    0
signal_bond    18c04320-3b9a-4728-9dd4-af256ce6c6a0
sip_call_id    7g_rvEeGAxaHE4RRhaXCdg..
sip_full_to    <sip:16417930191@FREESWITCHIP:5060>;tag=B69yrXNmcQv8m
sip_req_uri    16417930191@FREESWITCHIP:5060
sip_to_host    FREESWITCHIP
sip_to_port    5060
sip_to_user    16417930191
start_epoch    1670411843
start_stamp    2022-12-07 06:17:23
user_exists    false
write_codec    PCMU
RFC2822_DATE    Wed, 07 Dec 2022 06:17:23 -0500
answer_epoch    1670411847
answer_stamp    2022-12-07 06:17:27
bridge_epoch    1670411847
bridge_stamp    2022-12-07 06:17:27
channel_name    sofia/internal/15051001000@FREESWITCHIP:5060
flow_billsec    13
hangup_cause    NORMAL_CLEARING
max_forwards    70
number_alias    57914385
progressmsec    0
progressusec    0
rtp_use_ssrc    4087312730
sip_cid_type    pid
sip_from_tag    5157201f
sip_from_uri    15051001000@FREESWITCHIP:5060
sip_full_via    SIP/2.0/UDP 3CXPBXIP:5060;branch=z9hG4bK-524287-1---7e7d3559abd91b0a;rport=5060
sip_req_host    FREESWITCHIP
sip_req_port    5060
sip_req_user    16417930191
sip_via_host    3CXPBXIP
sip_via_port    5060
start_uepoch    1670411843614790
switch_m_sdp    v=0 o=Sonus_UAC 389772 43278 IN IP4 67.231.1.170 s=SIP Media Capabilities c=IN IP4 67.231.0.3 t=0 0 m=audio 13012 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 
switch_r_sdp    v=0 o=3cxPS 10989308542451712 12682446961115137 IN IP4 3CXPBXIP s=3cxPS Audio call c=IN IP4 3CXPBXIP t=0 0 m=audio 9310 RTP/AVP 9 0 8 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 
user_context    FREESWITCHIP
answer_uepoch    1670411847054787
bridge_uepoch    1670411847014787
flow_billmsec    13160
flow_billusec    13159994
hold_accum_ms    0
inherit_codec    true
record_stereo    true
sip_from_host    FREESWITCHIP
sip_from_port    5060
sip_from_user    15051001000
sip_full_from    "15051001000" <sip:15051001000@FREESWITCHIP:5060>;tag=5157201f
sip_via_rport    5060
Event-Date-GMT    Wed, 07 Dec 2022 11:17:23 GMT
Event-Sequence    829
bridge_channel    sofia/external/16417930191
call_direction    outbound
caller_id_name    57914385 -> this should be 15051001000
extension_uuid    d9528918-51c6-4713-9ec7-e96852cb29ce
last_bridge_to    18c04320-3b9a-4728-9dd4-af256ce6c6a0
local_media_ip    FREESWITCHIP
progress_epoch    0
sip_auth_realm    FREESWITCHIP
sip_authorized    true
sip_network_ip    3CXPBXIP
sip_term_cause    16
sip_user_agent    3CXPhoneSystem 18.0.6.861 (861)
FreeSWITCH-IPv4    FREESWITCHIP
FreeSWITCH-IPv6    ::1
ep_codec_string    mod_spandsp.G722@8000h@20i@64000b,CORE_PCM_MODULE.PCMU@8000h@20i@64000b,COR E_PCM_MODULE.PCMA@8000h@20i@64000b
hold_accum_usec    0
last_hold_epoch    0
originated_legs    18c04320-3b9a-4728-9dd4-af256ce6c6a0;16417930191;16417930191
progress_uepoch    0
remote_media_ip    3CXPBXIP
resurrect_epoch    0
sip_contact_uri    57914385@3CXPBXIP:5060
sip_received_ip    3CXPBXIP
sip_term_status    200
text_media_flow    disabled
Event-Date-Local    2022-12-07 06:17:23
audio_media_flow    sendrecv
callee_id_number    6417930191
caller_id_number    57914385
continue_on_fail    1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607
from_user_exists    false
last_bridge_role    originator
last_hold_uepoch    0
local_media_port    17660
originate_causes    18c04320-3b9a-4728-9dd4-af256ce6c6a0;NONE
resurrect_uepoch    0
rtp_audio_in_mos    4.50
sip_contact_host    3CXPBXIP
sip_contact_port    5060
sip_contact_user    57914385
sip_from_display    15051001000
sip_invite_stamp    1670411843614790
sip_network_port    5060
sip_number_alias    57914385
sip_via_protocol    udp
video_media_flow    disabled
directory-visible    true
hangup_cause_q850    16
limit_destination    !USER_BUSY
progress_mediasec    4
remote_media_port    9310
rtp_audio_recv_pt    0
rtp_local_sdp_str    v=0 o=FreeSWITCH 1670394187 1670394189 IN IP4 FREESWITCHIP s=FreeSWITCH c=IN IP4 FREESWITCHIP t=0 0 m=audio 17660 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv 
sip_auth_username    57914385
sip_received_port    5060
sofia_profile_url    sip:mod_sofia@FREESWITCHIP:5060
Event-Calling-File    sofia.c
caller_destination    16417930191
hold_accum_seconds    0
original_read_rate    8000
progress_mediamsec    3400
progress_mediausec    3399997
rtp_use_codec_name    PCMU
rtp_use_codec_rate    8000
rtp_use_timer_name    soft
sofia_profile_name    internal
FreeSWITCH-Hostname    freeswitch01-ro.mikesierra.ro
advertised_media_ip    FREESWITCHIP
bridge_hangup_cause    NORMAL_CLEARING
call_screen_enabled    false
current_application    bridge
hangup_after_bridge    true
original_read_codec    PCMU
profile_start_epoch    1670411843
profile_start_stamp    2022-12-07 06:17:23
requested_user_name    57914385
rtp_use_codec_ptime    20
sip_Remote-Party-ID    "15051001000" <sip:15051001000@FREESWITCHIP:5060>;party=calling
Event-Date-Timestamp    1670411843614790
endpoint_disposition    ANSWER
profile_start_uepoch    1670411843614790
progress_media_epoch    1670411847
progress_media_stamp    2022-12-07 06:17:27
rtp_use_codec_string    PCMU@8000h@20i
FreeSWITCH-Switchname    freeswitch01-ro.mikesierra.ro
originate_disposition    SUCCESS
progress_media_uepoch    1670411847014787
recovery_profile_name    internal
requested_domain_name    FREESWITCHIP
rtp_2833_recv_payload    101
rtp_2833_send_payload    101
Event-Calling-Function    sofia_handle_sip_i_invite
ignore_display_updates    true
remote_text_media_flow    inactive
rtp_audio_in_raw_bytes    83076
rtp_use_codec_channels    1
sip_from_user_stripped    15051001000
sip_hangup_disposition    recv_bye
sip_local_network_addr    FREESWITCHIP
directory-exten-visible    true
remote_audio_media_flow    sendrecv
remote_video_media_flow    inactive
rtp_audio_in_flaw_total    0
rtp_audio_out_raw_bytes    49020
current_application_data    sofia/gateway/1f80b26e-5530-4e0a-b781-3dd262b0b545/16417930191
last_sent_callee_id_name    16417930191
rtp_audio_in_media_bytes    83076
Event-Calling-Line-Number    10731
rtp_audio_in_packet_count    483
rtp_audio_out_media_bytes    49020
last_sent_callee_id_number    16417930191
origination_callee_id_name    16417930191
rtp_audio_in_mean_interval    20.00
rtp_audio_out_packet_count    285
rtp_audio_rtcp_octet_count    0
proto_specific_hangup_cause    sip:200
rtp_audio_rtcp_packet_count    0
rtp_last_audio_codec_string    PCMU@8000h@20i@1c
transfer_fallback_extension    operator
rtp_audio_in_largest_jb_size    0
rtp_audio_in_cng_packet_count    0
rtp_audio_in_jitter_loss_rate    0.00
rtp_audio_in_dtmf_packet_count    0
rtp_audio_in_jitter_burst_rate    0.00
rtp_audio_in_skip_packet_count    5
rtp_audio_out_cng_packet_count    0
rtp_audio_in_flush_packet_count    0
rtp_audio_in_media_packet_count    483
rtp_audio_in_quality_percentage    100.00
rtp_audio_out_dtmf_packet_count    0
rtp_audio_out_skip_packet_count    0
rtp_audio_in_jitter_max_variance    0.00
rtp_audio_in_jitter_min_variance    0.00
rtp_audio_in_jitter_packet_count    0
rtp_audio_out_media_packet_count    285


Application Log     
Name    Data
set     user_exists=false
set     from_user_exists=false
set     caller_destination=16417930191
set     caller_id_name=57914385
set     operator=1000
export     call_direction=local
export     call_direction=outbound
set     caller_id_number=57914385
set     RFC2822_DATE=Wed, 07 Dec 2022 06:17:23 -0500
export     origination_callee_id_name=16417930191
hash     insert/FREESWITCHIP-last_dial/57914385/16417930191
unset     call_timeout
set     hangup_after_bridge=true
set     effective_caller_id_name=
set     effective_caller_id_number=
set     inherit_codec=true
set     ignore_display_updates=true
set     callee_id_number=6417930191
set     continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,60 2,607
bridge     sofia/gateway/1f80b26e-5530-4e0a-b781-3dd262b0b545/16417930191


Call Flow: Attributes     
Name    Value
dialplan     XML
unique-id     4fe495b2-99c9-436d-9dd5-4ac51e629d2e
profile_index     1


Call Flow: Extension: Attributes     
Name    Value
name     user_exists
number     16417930191


Call Flow: Extension: Application     
Name    Data
set     caller_id_number=${caller_id_number}
set     RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}
export     origination_callee_id_name=${destination_number}
hash     insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}
unset     call_timeout
set     hangup_after_bridge=true
set     effective_caller_id_name=${outbound_caller_id_name}
set     effective_caller_id_number=${outbound_caller_id_number}
set     inherit_codec=true
set     ignore_display_updates=true
set     callee_id_number=6417930191
set     continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,60 2,607
bridge     sofia/gateway/1f80b26e-5530-4e0a-b781-3dd262b0b545/16417930191


Call Flow: Caller Profile     
Name    Value
ani     15051001000
uuid     1a6e8bd0-4b59-40a1-b9d8-8410e564b136
aniii     
rdnis     
source     mod_sofia
context     FREESWITCHIP
dialplan     XML
username     15051001000
chan_name     sofia/internal/15051001000@FREESWITCHIP:5060
originatee     
origination     Array
network_addr     3CXPBXIP
callee_id_name     16417930191
caller_id_name     15051001000
callee_id_number     16417930191
caller_id_number     15051001000
destination_number     16417930191


Call Flow: Times     
Name    Value
hangup_time     1670411856774784
bridged_time     1670411847014787
created_time     1670411843614790
answered_time     1670411847054787
progress_time     0
transfer_time     0
last_hold_time     0
resurrect_time     0
hold_accum_time     0
progress_media_time     1670411847014787
profile_created_time     1670411843614790

 

[SwaggerRO19]

Another update, at the time when I initially created the topic, I didn't prepare the PCAP's, but now I had a chance and I've reviewed he INVITE's, as they follow:

INVITE FROM 3CX PBX to FREESWITCH (FUSIONPBX):



INVITE FROM FREESWITCH (FUSIONPBX) TO THE CARRIER:



I've blurred out the essential data, but the main things that I observed are:

• In the invite coming from 3CX PBX, I'm correctly sending via FROM, PAID, PPID & RPID the FROM DID, which should be displayed. I've used in my topic the DID 15051001000 as an example.
• In the invite coming from FREESWITCH to the Carrier, I'm sending the CallerID (the DID that should be displayed) only in the RPID, because the FROM it's altered by Freeswitch to the user extension as it can be seen in the screenshot (second). The extension it's 5272443578. I left it unblurred in the screenshoot - the FROM field in the INVITE it's 5272443578@gw1.gateway.example when it should be 15051001000@gw1.gateway.example.

Please let me know if I can provide something else that might be relevant into solving this issue.

 

[SwaggerRO19]

I've escalated the issue to the Carrier to get a confirmation in what field they are looking for the outbound calls, and they confirmed the following:

We base routing on outbound off the FROM and your source number needs to be changed to a valid phone number what is showing now is your trunk number which can cause problems.

So I need a way to change how FREESWITCH sends the call to the Carrier in order to fix this issue, but no clue how.

 

[mingus]

The dialplan is currently doing a set for the caller id information. See below.
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/15051001000@FreeSWITCHPBXIP:5060 Action set(effective_caller_id_number=${outbound_caller_id_number})

Try changing the set to export. That should send the caller ID information here to the B-Leg. This should happen before bridging the call.

 

[SwaggerRO19]

I've adjusted the set to export, but nothing has improved. The same CLID it's being passed over to the outbound Carrier.

 

[mingus]

Try hardcoding the effective_caller_id_name and effective_caller_id_number again but make sure you enable inline to the dialplan line.

 

[mingus]

Based on your call detail record, it looks like you might need to set your variables as such.
set effective_caller_id_name=${caller_id_name}
set effective_caller_id_number=${caller_id_number}

 

[SwaggerRO19]

With the help of @mingus I've succeded on adding the RPID to the INVITE that was sent from FREESWITCH to the Carrier, and after escalating this issue to the Carrier, they switched how the SIP Trunk was looking at the CLID. It was set to look into the FROM field and not into the RPID. They adjusted this too on their end and now the CLID works like a charm!

Kudos again to @mingus for all the help!!

 

[demonspork]

What I think you missed is the "caller-id-in-from" field for the gateway. Edit the gateway, click Advanced, and set Caller ID in From to True would accomplish this in the future.

 

[mingus]

We tried that, but his provider did some weird authentication against the "from" header that caused the invite to be rejected. Having his provider look at the rpid was the answer in this case.