SRTP not negotiated when using ring group

trumee · Aug 18, 2024

Hello,

I have a Yealink phone (W60B) setup with TLS sip and mandatory SRTP mandatory.

The Yealink extension (201) has this dialstring assigned following guidance from documentation (tweaked),

{rtp_secure_media=true,sip_invite_domain=${domain_name},leg_timeout=${call_timeout},presence_id=${dialed_user}@${dialed_domain}}${sofia_contact(*/${dialed_user}@${dialed_domain})}

My upstream trunk does no support SRTP. The inbound call work fine if setup a dial plan like so,

<extension name="+118040927625" continue="false" uuid="51243bf0-245e-4a49-b110-020a1f2c5084">
<condition field="destination_number" expression="^\+(118040927625)$">
<action application="export" data="call_direction=inbound" inline="true"/>
<action application="set" data="domain_uuid=6eb1a147-7faf-4898-b1ad-73636dc149d9" inline="true"/>
<action application="set" data="domain_name=pbx.mydomain.com" inline="true"/>
<action application="transfer" data="201 XML pbx.mydomain.com"/>
</condition>
</extension>

However if i use a ringgroup instead with the transfer line above as,

<action application="transfer" data="600 XML pbx.mydomain.com"/>

and

the call doesnt go through. I get an [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]. The SDP offered to the Yealink phone does not have crypto lines.

2024-08-18 16:26:52.463035 83.23% [DEBUG] sofia_glue.c:1662 sofia/internal/201@172.16.2.13:12030 sending invite version: 1.10.11 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1723982788 1723982789 IN IP4 172.16.2.12
s=FreeSWITCH
c=IN IP4 172.16.2.12
t=0 0
m=audio 15624 RTP/AVP 8 0 102 9 101 13 103 104
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=rtpmap:13 CN/8000
a=rtpmap:104 CN/48000
a=ptime:20
a=sendrecv

So SRTP does not work with Ring Group but it does work if extension is called directly. Is there any fix for this?

pbxgeek · Aug 19, 2024

A potential approach to setting the value without directly modifying the LUA script for ring groups is to create a new dialplan entry that handles this task.

Code:

<action application="set" data="rtp_secure_media=true"/>

trumee · Aug 19, 2024

Unfortunately, i still get an [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION], [terminated][488] error after changing the dial plan,

<extension name="+118040927625" continue="false" uuid="51243bf0-245e-4a49-b110-020a1f2c5084">
<condition field="destination_number" expression="^\+(118040927625)$">
<action application="export" data="call_direction=inbound" inline="true"/>
<action application="set" data="domain_uuid=6eb1a147-7faf-4898-b1ad-73636dc149d9" inline="true"/>
<action application="set" data="domain_name=pbx.mydomain.com" inline="true"/>
<action application="set" data="sip_secure_media=true"/>
<action application="transfer" data="600 XML pbx.mydomain.com"/>

</condition>
</extension>

pbxgeek · Aug 19, 2024

In your example, I see

Code:

sip_secure_media="true"

instead of

Code:

rtp_secure_media="true"

I would also try to export the variable since you are going to need it on the b-leg

Code:

<action application="export" data="rtp_secure_media=true"/>

And you can try to set them inline. This helps in some cases.

Code:

<action application="set" data="rtp_secure_media=true" inline="true"/>
<action application="export" data="rtp_secure_media=true" inline="true"/>

trumee · Aug 20, 2024

Thanks that was a typo. I have made the changes as you suggested. Unfortunately, it does not fix the problem. A trace of PSTN call to the ring group is shown below. You can see that rtp_secure_media is being set, but SDP does not have crypto lines.

Code:

+OK log level  [7]
2024-08-20 03:28:36.911278 90.00% [NOTICE] switch_channel.c:1142 New Channel sofia/btel/1034568542@nowhere [53816896-c4e3-4e90-ba01-f8201402a9a2]
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_NEW (Cur 1 Tot 1)
2024-08-20 03:28:36.911278 90.00% [INFO] sofia.c:10459 sofia/btel/1034568542@nowhere receiving invite from 10.232.142.146:5060 version: 1.10.11 -release 64bit call-id: asbc066o2w6wz03z0434o510n1z7vy16426g@10.232.136.227
2024-08-20 03:28:36.911278 90.00% [DEBUG] sofia.c:10553 verifying acl "providers" for ip/port 10.232.142.146:0.
2024-08-20 03:28:36.911278 90.00% [DEBUG] sofia.c:10582 IP 10.232.142.146 Approved by acl "providers[]". Access Granted.
2024-08-20 03:28:36.911278 90.00% [DEBUG] sofia.c:7493 Channel sofia/btel/1034568542@nowhere entering state [received][100]
2024-08-20 03:28:36.911278 90.00% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=- 390779818 390779818 IN IP4 10.232.142.170
s=SBC call
c=IN IP4 10.232.142.170
t=0 0
m=audio 31284 RTP/AVP 108 102 8 0 18 116
a=rtpmap:108 AMR/8000
a=fmtp:108 mode-change-neighbor=1;mode-change-period=2
a=rtpmap:102 AMR/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:116 telephone-event/8000
a=ptime:20
a=maxptime:20
a=3gOoBTC

2024-08-20 03:28:36.911278 90.00% [DEBUG] sofia.c:7906 (sofia/btel/1034568542@nowhere) State Change CS_NEW -> CS_INIT
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:600 (sofia/btel/1034568542@nowhere) State NEW
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_INIT (Cur 1 Tot 1)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:624 (sofia/btel/1034568542@nowhere) State INIT
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_sofia.c:97 sofia/btel/1034568542@nowhere SOFIA INIT
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:40 sofia/btel/1034568542@nowhere Standard INIT
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:48 (sofia/btel/1034568542@nowhere) State Change CS_INIT -> CS_ROUTING
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:624 (sofia/btel/1034568542@nowhere) State INIT going to sleep
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_ROUTING (Cur 1 Tot 1)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_channel.c:2399 (sofia/btel/1034568542@nowhere) Callstate Change DOWN -> RINGING
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:640 (sofia/btel/1034568542@nowhere) State ROUTING
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_sofia.c:158 sofia/btel/1034568542@nowhere SOFIA ROUTING
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:230 sofia/btel/1034568542@nowhere Standard ROUTING
2024-08-20 03:28:36.911278 90.00% [INFO] mod_dialplan_xml.c:639 Processing 01034568542 <01034568542>->+118040927625 in context public
2024-08-20 03:28:36.911278 90.00% [NOTICE] switch_cpp.cpp:1466 [xml_handler] multiple key:dialplan:public
Dialplan: sofia/btel/1034568542@nowhere parsing [public->caller-details] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/btel/1034568542@nowhere Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere export(call_direction=inbound)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/btel/1034568542@nowhere Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(caller_destination=+118040927625)
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [caller_destination]=[+118040927625]
Dialplan: sofia/btel/1034568542@nowhere Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(caller_id_name=01034568542)
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [caller_id_name]=[01034568542]
Dialplan: sofia/btel/1034568542@nowhere Action set(caller_id_number=${caller_id_number}) 
Dialplan: sofia/btel/1034568542@nowhere parsing [public->+118040927625] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [+118040927625] destination_number(+118040927625) =~ /^\+(118040927625)$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere export(call_direction=inbound)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/btel/1034568542@nowhere Action set(domain_uuid=6eb1a147-7faf-4898-b1ad-73636dc149d9) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(domain_uuid=6eb1a147-7faf-4898-b1ad-73636dc149d9)
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [domain_uuid]=[6eb1a147-7faf-4898-b1ad-73636dc149d9]
Dialplan: sofia/btel/1034568542@nowhere Action set(domain_name=pbx.mydomain.com) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(domain_name=pbx.mydomain.com)
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [domain_name]=[pbx.mydomain.com]
Dialplan: sofia/btel/1034568542@nowhere Action set(rtp_secure_media=true) 
Dialplan: sofia/btel/1034568542@nowhere Action transfer(600 XML pbx.mydomain.com) 
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:281 (sofia/btel/1034568542@nowhere) State Change CS_ROUTING -> CS_EXECUTE
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:640 (sofia/btel/1034568542@nowhere) State ROUTING going to sleep
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:647 (sofia/btel/1034568542@nowhere) State EXECUTE
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_sofia.c:213 sofia/btel/1034568542@nowhere SOFIA EXECUTE
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:323 sofia/btel/1034568542@nowhere Standard EXECUTE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(caller_id_number=01034568542)
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [caller_id_number]=[01034568542]
2024-08-20 03:28:36.911278 90.00% [CONSOLE] sofia_presence.c:1621 Event Thread Started
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(rtp_secure_media=true)
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [rtp_secure_media]=[true]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere transfer(600 XML pbx.mydomain.com)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_ivr.c:2296 (sofia/btel/1034568542@nowhere) State Change CS_EXECUTE -> CS_ROUTING
2024-08-20 03:28:36.911278 90.00% [NOTICE] switch_ivr.c:2303 Transfer sofia/btel/1034568542@nowhere to XML[600@pbx.mydomain.com]
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:647 (sofia/btel/1034568542@nowhere) State EXECUTE going to sleep
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_ROUTING (Cur 1 Tot 1)
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:640 (sofia/btel/1034568542@nowhere) State ROUTING
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_sofia.c:149 Call appears to be already acknowledged
2024-08-20 03:28:36.911278 90.00% [DEBUG] mod_sofia.c:158 sofia/btel/1034568542@nowhere SOFIA ROUTING
2024-08-20 03:28:36.911278 90.00% [DEBUG] switch_core_state_machine.c:230 sofia/btel/1034568542@nowhere Standard ROUTING
2024-08-20 03:28:36.911278 90.00% [INFO] mod_dialplan_xml.c:639 Processing 01034568542 <01034568542>->600 in context pbx.mydomain.com
2024-08-20 03:28:36.931239 90.00% [NOTICE] switch_cpp.cpp:1466 [xml_handler] multiple key:dialplan:pbx.mydomain.com
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->user_exists] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/btel/1034568542@nowhere Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(user_exists=false)
2024-08-20 03:28:36.931239 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [user_exists]=[false]
Dialplan: sofia/btel/1034568542@nowhere Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(from_user_exists=false)
2024-08-20 03:28:36.931239 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [from_user_exists]=[false]
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->caller-details] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [caller-details] ${caller_destination}(+118040927625) =~ /^$/ break=never
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->global-variables] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/btel/1034568542@nowhere Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->domain-variables] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/btel/1034568542@nowhere Action export(origination_callee_id_name=${caller_destination}) 
Dialplan: sofia/btel/1034568542@nowhere Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(operator=1000)
2024-08-20 03:28:36.931239 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [operator]=[1000]
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->clear_sip_auto_answer] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->is_loopback] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->call-direction] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [call-direction] ${call_direction}(inbound) =~ /^$/ break=never
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->user_record] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->rtp_has_crypto] continue=true
Dialplan: sofia/btel/1034568542@nowhere 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/btel/1034568542@nowhere parsing [pbx.mydomain.com->redial] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [redial] destination_number(600) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/btel/1034568542@nowhere Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->speed_dial] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [speed_dial] destination_number(600) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->default_caller_id] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [default_caller_id] ${call_direction}(inbound) =~ /outbound/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->user_hold_music] continue=true
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->gateway_lko.5d] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [gateway_lko.5d] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [gateway_lko.5d] destination_number(600) =~ /^5(\+)?(\d+)$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->ims.btel.in.0091d320] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [ims.btel.in.0091d320] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [ims.btel.in.0091d320] destination_number(600) =~ /^(\+|00)(91)(\d{3,20})$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->ims.btel.in.1800d7] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [ims.btel.in.1800d7] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [ims.btel.in.1800d7] destination_number(600) =~ /^(1800\d{7})$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->ims.btel.in.121121d] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [ims.btel.in.121121d] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [ims.btel.in.121121d] destination_number(600) =~ /^(121|121\d+)$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->gateway_lko.301303304323] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [gateway_lko.301303304323] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [gateway_lko.301303304323] destination_number(600) =~ /^(301|303|304|323)$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->ims.btel.in.d11] continue=false
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [ims.btel.in.d11] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Regex (FAIL) [ims.btel.in.d11] destination_number(600) =~ /^(\d{11})$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere parsing [pbx.mydomain.com->ringgroup_600] continue=
Dialplan: sofia/btel/1034568542@nowhere Regex (PASS) [ringgroup_600] destination_number(600) =~ /^600$/ break=on-false
Dialplan: sofia/btel/1034568542@nowhere Action ring_ready() 
Dialplan: sofia/btel/1034568542@nowhere Action set(ring_group_uuid=81d60bf3-5283-432f-9a36-0de8c4c86124) 
Dialplan: sofia/btel/1034568542@nowhere Action lua(app.lua ring_groups) 
2024-08-20 03:28:36.931239 90.00% [DEBUG] switch_core_state_machine.c:281 (sofia/btel/1034568542@nowhere) State Change CS_ROUTING -> CS_EXECUTE
2024-08-20 03:28:36.931239 90.00% [DEBUG] switch_core_state_machine.c:640 (sofia/btel/1034568542@nowhere) State ROUTING going to sleep
2024-08-20 03:28:36.931239 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2024-08-20 03:28:36.931239 90.00% [DEBUG] switch_core_state_machine.c:647 (sofia/btel/1034568542@nowhere) State EXECUTE
2024-08-20 03:28:36.931239 90.00% [DEBUG] mod_sofia.c:213 sofia/btel/1034568542@nowhere SOFIA EXECUTE
2024-08-20 03:28:36.931239 90.00% [DEBUG] switch_core_state_machine.c:323 sofia/btel/1034568542@nowhere Standard EXECUTE
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(RFC2822_DATE=Tue, 20 Aug 2024 03:28:36 +0000)
2024-08-20 03:28:36.931239 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [RFC2822_DATE]=[Tue, 20 Aug 2024 03:28:36 +0000]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere export(origination_callee_id_name=+118040927625)
2024-08-20 03:28:36.931239 90.00% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [origination_callee_id_name]=[+118040927625]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere hash(insert/pbx.mydomain.com-last_dial/01034568542/600)
EXECUTE [depth=0] sofia/btel/1034568542@nowhere ring_ready()
2024-08-20 03:28:36.931239 90.00% [NOTICE] mod_sofia.c:2514 Ring-Ready sofia/btel/1034568542@nowhere!
2024-08-20 03:28:36.931239 90.00% [DEBUG] sofia.c:7493 Channel sofia/btel/1034568542@nowhere entering state [early][180]
2024-08-20 03:28:36.931239 90.00% [NOTICE] mod_dptools.c:1113 Ring Ready sofia/btel/1034568542@nowhere!
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(ring_group_uuid=81d60bf3-5283-432f-9a36-0de8c4c86124)
2024-08-20 03:28:36.931239 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [ring_group_uuid]=[81d60bf3-5283-432f-9a36-0de8c4c86124]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere lua(app.lua ring_groups)
EXECUTE [depth=0] sofia/btel/1034568542@nowhere ring_ready()
2024-08-20 03:28:36.951275 90.00% [NOTICE] mod_dptools.c:1113 Ring Ready sofia/btel/1034568542@nowhere!
2024-08-20 03:28:36.951275 90.00% [DEBUG] switch_cpp.cpp:774 CoreSession::setVariable('call_timeout', '30')
2024-08-20 03:28:36.951275 90.00% [NOTICE] switch_cpp.cpp:1466 [ring group] domain_name: pbx.mydomain.com
2024-08-20 03:28:36.951275 90.00% [NOTICE] switch_cpp.cpp:1466 [ring group] destination_number: 201
2024-08-20 03:28:36.951275 90.00% [NOTICE] switch_cpp.cpp:1466 [ring group] destination_delay: 0
2024-08-20 03:28:36.951275 90.00% [NOTICE] switch_cpp.cpp:1466 [ring group] destination_timeout: 30
2024-08-20 03:28:36.951275 90.00% [NOTICE] switch_cpp.cpp:1466 [ring group] destination_prompt: 
2024-08-20 03:28:36.951275 90.00% [DEBUG] switch_cpp.cpp:774 CoreSession::setVariable('ringback', 'tone_stream://%(400,200,425,375);%(400,2000,425,375);loops=-1')
2024-08-20 03:28:36.951275 90.00% [DEBUG] switch_cpp.cpp:774 CoreSession::setVariable('transfer_ringback', 'tone_stream://%(400,200,425,375);%(400,2000,425,375);loops=-1')
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(call_timeout=30)
2024-08-20 03:28:36.951275 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [call_timeout]=[30]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(group_confirm_key=exec)
2024-08-20 03:28:36.951275 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [group_confirm_key]=[exec]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(group_confirm_file=lua /usr/share/freeswitch/scripts/confirm.lua)
2024-08-20 03:28:36.951275 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [group_confirm_file]=[lua /usr/share/freeswitch/scripts/confirm.lua]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(hangup_after_bridge=true)
2024-08-20 03:28:36.971277 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere set(continue_on_fail=true)
2024-08-20 03:28:36.971277 90.00% [DEBUG] mod_dptools.c:1671 SET sofia/btel/1034568542@nowhere [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/btel/1034568542@nowhere bind_digit_action(local,*2,exec:record_session,/var/lib/freeswitch/recordings/pbx.mydomain.com/archive/2024/Aug/20/53816896-c4e3-4e90-ba01-f8201402a9a2.wav,peer)
2024-08-20 03:28:36.971277 90.00% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'local'
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *2/local/0 callback: 0x74adbf5a9df0 data: 0x74ad2c031cb0
EXECUTE [depth=0] sofia/btel/1034568542@nowhere bind_digit_action(local,*5,api:uuid_record,53816896-c4e3-4e90-ba01-f8201402a9a2 mask /var/lib/freeswitch/recordings/pbx.mydomain.com/archive/2024/Aug/20/53816896-c4e3-4e90-ba01-f8201402a9a2.wav,peer)
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *5/local/0 callback: 0x74adbf5a9df0 data: 0x74ad2c031f38
EXECUTE [depth=0] sofia/btel/1034568542@nowhere bind_digit_action(local,*6,api:uuid_record,53816896-c4e3-4e90-ba01-f8201402a9a2 unmask /var/lib/freeswitch/recordings/pbx.mydomain.com/archive/2024/Aug/20/53816896-c4e3-4e90-ba01-f8201402a9a2.wav,peer)
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *6/local/0 callback: 0x74adbf5a9df0 data: 0x74ad2c0321d8
EXECUTE [depth=0] sofia/btel/1034568542@nowhere digit_action_set_realm(local)
2024-08-20 03:28:36.971277 90.00% [NOTICE] switch_cpp.cpp:1466 [ring group] app_data: {ignore_early_media=true}[sip_invite_domain=pbx.mydomain.com,call_direction=inbound,confirm=false,,leg_timeout=30,leg_delay_start=0,dialed_extension=201,hold_music=local_stream://default,presence_id=201@pbx.mydomain.com,extension_uuid=dd85de84-febf-4454-88a7-e02ef626f493]sofia/internal/sip:201@172.16.2.13:12062;transport=TLS
EXECUTE [depth=0] sofia/btel/1034568542@nowhere bridge({ignore_early_media=true}[sip_invite_domain=pbx.mydomain.com,call_direction=inbound,confirm=false,,leg_timeout=30,leg_delay_start=0,dialed_extension=201,hold_music=local_stream://default,presence_id=201@pbx.mydomain.com,extension_uuid=dd85de84-febf-4454-88a7-e02ef626f493]sofia/internal/sip:201@172.16.2.13:12062;transport=TLS)
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_channel.c:1288 sofia/btel/1034568542@nowhere EXPORTING[export_vars] [call_direction]=[inbound] to event
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_channel.c:1288 sofia/btel/1034568542@nowhere EXPORTING[export_vars] [call_direction]=[inbound] to event
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_channel.c:1288 sofia/btel/1034568542@nowhere EXPORTING[export_vars] [origination_callee_id_name]=[+118040927625] to event
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_originate.c:2863 Parsing session specific variables
2024-08-20 03:28:36.971277 90.00% [NOTICE] switch_channel.c:1142 New Channel sofia/internal/201@172.16.2.13:12062 [cfc6b3ec-2fac-4c93-9df9-299f1a8c796e]
2024-08-20 03:28:36.971277 90.00% [DEBUG] mod_sofia.c:5110 (sofia/internal/201@172.16.2.13:12062) State Change CS_NEW -> CS_INIT
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_originate.c:3171 sofia/internal/201@172.16.2.13:12062 Setting leg timeout to 30
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/201@172.16.2.13:12062) Running State Change CS_INIT (Cur 2 Tot 2)
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/201@172.16.2.13:12062) State INIT
2024-08-20 03:28:36.971277 90.00% [DEBUG] mod_sofia.c:97 sofia/internal/201@172.16.2.13:12062 SOFIA INIT
2024-08-20 03:28:36.971277 90.00% [INFO] sofia_glue.c:1659 sofia/internal/201@172.16.2.13:12062 sending invite call-id: (null)
2024-08-20 03:28:36.971277 90.00% [DEBUG] sofia_glue.c:1662 sofia/internal/201@172.16.2.13:12062 sending invite version: 1.10.11 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1724106384 1724106385 IN IP4 172.16.2.12
s=FreeSWITCH
c=IN IP4 172.16.2.12
t=0 0
m=audio 18132 RTP/AVP 8 0 9 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:40 sofia/internal/201@172.16.2.13:12062 Standard INIT
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/201@172.16.2.13:12062) State Change CS_INIT -> CS_ROUTING
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/201@172.16.2.13:12062) State INIT going to sleep
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/201@172.16.2.13:12062) Running State Change CS_ROUTING (Cur 2 Tot 2)
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/201@172.16.2.13:12062) State ROUTING
2024-08-20 03:28:36.971277 90.00% [DEBUG] mod_sofia.c:158 sofia/internal/201@172.16.2.13:12062 SOFIA ROUTING
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_ivr_originate.c:67 (sofia/internal/201@172.16.2.13:12062) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/201@172.16.2.13:12062) State ROUTING going to sleep
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/201@172.16.2.13:12062) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 2)
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/201@172.16.2.13:12062) State CONSUME_MEDIA
2024-08-20 03:28:36.971277 90.00% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/201@172.16.2.13:12062) State CONSUME_MEDIA going to sleep
2024-08-20 03:28:36.971277 90.00% [DEBUG] sofia.c:7493 Channel sofia/internal/201@172.16.2.13:12062 entering state [calling][0]
2024-08-20 03:28:37.071284 90.00% [DEBUG] sofia.c:7493 Channel sofia/internal/201@172.16.2.13:12062 entering state [terminated][488]
2024-08-20 03:28:37.071284 90.00% [NOTICE] sofia.c:8735 Hangup sofia/internal/201@172.16.2.13:12062 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/201@172.16.2.13:12062) Running State Change CS_HANGUP (Cur 2 Tot 2)
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/201@172.16.2.13:12062) Callstate Change DOWN -> HANGUP
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/201@172.16.2.13:12062) State HANGUP
2024-08-20 03:28:37.071284 90.00% [DEBUG] mod_sofia.c:469 Channel sofia/internal/201@172.16.2.13:12062 hanging up, cause: INCOMPATIBLE_DESTINATION
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:59 sofia/internal/201@172.16.2.13:12062 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/201@172.16.2.13:12062) State HANGUP going to sleep
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/201@172.16.2.13:12062) State Change CS_HANGUP -> CS_REPORTING
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/201@172.16.2.13:12062) Running State Change CS_REPORTING (Cur 2 Tot 2)
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/201@172.16.2.13:12062) State REPORTING
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:168 sofia/internal/201@172.16.2.13:12062 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/201@172.16.2.13:12062) State REPORTING going to sleep
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/201@172.16.2.13:12062) State Change CS_REPORTING -> CS_DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_session.c:1744 Session 2 (sofia/internal/201@172.16.2.13:12062) Locked, Waiting on external entities
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_ivr_originate.c:4056 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2024-08-20 03:28:37.071284 90.00% [NOTICE] switch_core_session.c:1762 Session 2 (sofia/internal/201@172.16.2.13:12062) Ended
2024-08-20 03:28:37.071284 90.00% [NOTICE] switch_core_session.c:1766 Close Channel sofia/internal/201@172.16.2.13:12062 [CS_DESTROY]
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/201@172.16.2.13:12062) Running State Change CS_DESTROY (Cur 1 Tot 2)
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/201@172.16.2.13:12062) State DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] mod_sofia.c:380 sofia/internal/201@172.16.2.13:12062 SOFIA DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:175 sofia/internal/201@172.16.2.13:12062 Standard DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/201@172.16.2.13:12062) State DESTROY going to sleep
2024-08-20 03:28:37.071284 90.00% [INFO] mod_dptools.c:3635 Originate Failed.  Cause: INCOMPATIBLE_DESTINATION
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_cpp.cpp:1210 sofia/btel/1034568542@nowhere destroy/unlink session from object
2024-08-20 03:28:37.071284 90.00% [NOTICE] switch_core_state_machine.c:382 sofia/btel/1034568542@nowhere has executed the last dialplan instruction, hanging up.
2024-08-20 03:28:37.071284 90.00% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/btel/1034568542@nowhere [CS_EXECUTE] [NORMAL_CLEARING]
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:647 (sofia/btel/1034568542@nowhere) State EXECUTE going to sleep
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_HANGUP (Cur 1 Tot 2)
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:844 (sofia/btel/1034568542@nowhere) Callstate Change RINGING -> HANGUP
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:846 (sofia/btel/1034568542@nowhere) State HANGUP
2024-08-20 03:28:37.071284 90.00% [DEBUG] mod_sofia.c:463 sofia/btel/1034568542@nowhere Overriding SIP cause 480 with 488 from the other leg
2024-08-20 03:28:37.071284 90.00% [DEBUG] mod_sofia.c:469 Channel sofia/btel/1034568542@nowhere hanging up, cause: NORMAL_CLEARING
2024-08-20 03:28:37.071284 90.00% [DEBUG] mod_sofia.c:614 Responding to INVITE with: 488
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:59 sofia/btel/1034568542@nowhere Standard HANGUP, cause: NORMAL_CLEARING
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:846 (sofia/btel/1034568542@nowhere) State HANGUP going to sleep
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:616 (sofia/btel/1034568542@nowhere) State Change CS_HANGUP -> CS_REPORTING
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/btel/1034568542@nowhere) Running State Change CS_REPORTING (Cur 1 Tot 2)
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:932 (sofia/btel/1034568542@nowhere) State REPORTING
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:168 sofia/btel/1034568542@nowhere Standard REPORTING, cause: NORMAL_CLEARING
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:932 (sofia/btel/1034568542@nowhere) State REPORTING going to sleep
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:607 (sofia/btel/1034568542@nowhere) State Change CS_REPORTING -> CS_DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_session.c:1744 Session 1 (sofia/btel/1034568542@nowhere) Locked, Waiting on external entities
2024-08-20 03:28:37.071284 90.00% [NOTICE] switch_core_session.c:1762 Session 1 (sofia/btel/1034568542@nowhere) Ended
2024-08-20 03:28:37.071284 90.00% [NOTICE] switch_core_session.c:1766 Close Channel sofia/btel/1034568542@nowhere [CS_DESTROY]
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:735 (sofia/btel/1034568542@nowhere) Running State Change CS_DESTROY (Cur 0 Tot 2)
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:745 (sofia/btel/1034568542@nowhere) State DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] mod_sofia.c:380 sofia/btel/1034568542@nowhere SOFIA DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:175 sofia/btel/1034568542@nowhere Standard DESTROY
2024-08-20 03:28:37.071284 90.00% [DEBUG] switch_core_state_machine.c:745 (sofia/btel/1034568542@nowhere) State DESTROY going to sleep

pbxgeek · Aug 20, 2024

Let me ask what changes you made to your SIP profiles to get TLS set up. It's not configured out of the box. It is starting to look like freeswitch doesn't know how to apply SRTP

trumee · Aug 20, 2024

I have SSL enabled in variables with certificates in place,

The internal profile has default setting,

If i make a call to *97 from an extension, i do get crypto as the following screenshot and trace shows

Code:

2024-08-20 16:36:13.509230 91.27% [DEBUG] switch_core_media.c:9003 sofia/internal/201@pbx.mydomain.com:5060 Set rtp dtmf delay to 40
2024-08-20 16:36:13.509230 91.27% [INFO] switch_rtp.c:4366 Activating audio Secure RTP SEND
2024-08-20 16:36:13.509230 91.27% [INFO] switch_rtp.c:4344 Activating audio Secure RTP RECV
2024-08-20 16:36:13.509230 91.27% [DEBUG] mod_sofia.c:914 Local SDP sofia/internal/201@pbx.mydomain.com:5060:
v=0
o=FreeSWITCH 1724154829 1724154830 IN IP4 172.16.2.12
s=FreeSWITCH
c=IN IP4 172.16.2.12
t=0 0
m=audio 16944 RTP/SAVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:xLRuYfs2VkczUtYE7pEF+x2TV0d110C0/3mue6fw

2024-08-20 16:36:13.509230 91.27% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2024-08-20 16:36:13.509230 91.27% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2024-08-20 16:36:13.509230 91.27% [NOTICE] mod_dptools.c:1406 Channel [sofia/internal/201@pbx.mydomain.com:5060] has been answered

Also, if i call between two extensions i get SRTP. No issues.

The only issue i have is when i get a call from outside trunk (PSTN), then i get an INCOMPATIBLE_DESTINATION. I have not touched anything in the external profile and it is set to external_ssl_enable is set to false.

Finally, i found this. Is this required in fpbx?

pbxgeek · Aug 20, 2024

Interesting post.
rtp_secure_media=mandatory
I didn't know that existed. Every day, you learn something new about Freeswitch. Would you please give it a try and let us know?

trumee · Aug 21, 2024

That didn't work.

What i am trying to do here is pretty straightforward and i believe this has worked in the past. This is new installation and maybe the fusionpbx code has become worse than before.

pbxgeek · Aug 21, 2024

I'm going to test this on my server and get my hands on the Yealink phone in the next couple of days. I'll let you know what I find.

trumee · Aug 22, 2024

Sure. Yealink phone is not necessary, any softphone will do too. I my case 201 is Yealink and 202 is Groundwire on Android.

Here is the setup:

1. Create two extensions say 201/202, and specify "{rtp_secure_media=true,sip_invite_domain=${domain_name},leg_timeout=${call_timeout},presence_id=${dialed_user}@${dialed_domain}}${sofia_contact(*/${dialed_user}@${dialed_domain})}" in its 'Dial String' definition.
2. Setup the clients to use TLS and SRTP.
3. Make a call between 201 and 202 and confirm SRTP is working.
4. Setup a Ring group with extension 600, and specify 201 and 202, and use Strategy 'Simultaneous'.
5. Setup Inbound Route Destination to 600 with "<action application="transfer" data="600 XML pbx.mydomain.com"/>"
6. Call 600 from extension 201 and notice it fail with "INCOMPATIBLE_DESTINATION"

KNERD · Aug 22, 2024

I see a CODEC problem, not a TLS error

trumee · Aug 22, 2024

KNERD said:
I see a CODEC problem, not a TLS error

Can you elaborate, where do you see the error?

pbxgeek · Aug 22, 2024

My test shows that I'm sending both secure and insecure media. So, the device can choose what they can use.

Code:

v=0
o=FreeSWITCH 1724325946 1724325947 IN IP4 
s=FreeSWITCH
c=IN IP4 45.33.51.29
t=0 0
m=audio 22320 RTP/SAVP 0 9 8 102 101 13 103 104
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=crypto:7 AES_CM_128_HMAC_SHA1_80 inline:MujTXcSS7glYEUo9vEqUDM1FFn6XoYXn1ty5Sn8A
a=rtpmap:13 CN/8000
a=rtpmap:104 CN/48000
a=ptime:20
a=sendrecv
m=audio 22320 RTP/AVP 0 9 8 102 101 13 103 104
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=rtpmap:13 CN/8000
a=rtpmap:104 CN/48000
a=ptime:20
a=sendrecv

I found this the best way to handle the issue of some devices being unable to do TLS.
Either way, it's a configuration issue on your end since you see the secure media stripped down. I'll follow up later with my settings to see what else you are missing.

Regarding the codec, you are sending G722 to the device. I assume it can handle it but it is worth double-checking as per @KNERD

pbxgeek · Aug 22, 2024

IMHO, The codec is unlikely the cause, or at least not the whole issue. You are sending insecure media, and the device is set to use TLS only with Compulsory mode. It would fail for sure at the negotiation step.

trumee · Aug 22, 2024

I stripped down the codec to PCMU/PCMA, and made a call to ring group 600. It failed again. Here is the log.

@pbxgeek What magic did you get to get both RTP/SAVP and RTP/AVP in the same message?

pbxgeek · Aug 22, 2024

I was able to reproduce your issue. Ring Group stripped my SRTP media, too. I didn't do the test correctly the first time around, so it comes out as insecure media on the other side. It has to be the LUA script that does it unless I'm missing something, too. I'm going to play with it a bit to see how it can be resolved

pbxgeek · Aug 23, 2024

I did some more extensive testing and must take my last post back. I found that I was originally correct in saying that my ring group is sending both media types in the invite, and the device decides which one to use. I do it because not all devices support SRTP and TLS.

This is what it looks like

Code:

2024-08-22 22:38:39.258585 95.37% [DEBUG] sofia_glue.c:1662 sofia/internal/700@192.168.4.32:56412 sending invite version: 1.10.11 -release-25-f24064f7c9 64bit
Local SDP:
v=0
o=FreeSWITCH 1724368869 1724368870 IN IP4
s=FreeSWITCH
c=IN IP4 45.33.51.29
t=0 0
m=audio 22650 RTP/SAVP 0 9 8 102 101 13 103 104
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=crypto:7 AES_CM_128_HMAC_SHA1_80 inline:+g1FWgVczbnPDpilRQHK5i6kRjHEPcd33zdVd+27
a=rtpmap:13 CN/8000
a=rtpmap:104 CN/48000
a=ptime:20
a=sendrecv
m=audio 22650 RTP/AVP 0 9 8 102 101 13 103 104
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=rtpmap:13 CN/8000
a=rtpmap:104 CN/48000
a=ptime:20
a=sendrecv

I tested with two devices. One that supports SRTP and one that doesn't and the results were as expected. It ultimately negotiated the media that both legs supported. So you are missing something in your config to make it work. Perhaps these records in the SIP variables are the key since they weren't mentioned before.

Also I want to mention that I don't have any special dial strings under extensions. It works fine without it. And don't forget to flush cache and reboot FreeSWITCH.

trumee · Aug 23, 2024

@pbxgeek Thanks you, your tips help me solve the problem.

This is the setup which works.
1. Setup the extensions 201 and 202 (without custom dial string)
2. Specify rtp_secure_media=optional:AES_CM_128_HMAC_SHA1_80 in variables
3. In groundwire sip app, Set Preferences>Security>SRTP>SDES, Enable only AES_CM_128_HMAC_SHA1_80

With this SRTP in ring group works!

I did not have to setup rtp_sdes_suites or rtp_secure_media_outbound. Infact if i setup rtp_sdes_suites i was getting an error. Can you post your setting in text form since the screenshot is not complete?

pbxgeek · Aug 23, 2024

Fantastic!
Here is my rtp_sdes_suites. But it's not a template. It may need some tweaking.

Code:

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

SRTP not negotiated when using ring group

New Member

Active Member

New Member

Active Member

New Member

Active Member

New Member

Active Member

New Member

Active Member

New Member

New Member

New Member

Active Member

Active Member

New Member

Active Member

Active Member

New Member

Active Member