SOLVED Calls are routed to voicemail. SIP/2.0 400 Bad Request

Status
Not open for further replies.
P

pbxgeek

Active Member
Jan 19, 2021
183
64
28
37
Good day everyone,
I beg someone to explain me what's happening with my calls. Setup a backup server and testing everything. When I call from one extension to another I get SIP/2.0 400 Bad Request error. Here is INVITE and RESPONSE:

Code: 
INVITE sip:100@192.168.1.73:46139;transport=tls SIP/2.0
Via: SIP/2.0/TLS x.x.x.x:36001;rport;branch=z9hG4bKB9KHHS88ZZK2K
Route: <sip:100@x.x.x.x:46139>;transport=tls
Max-Forwards: 69
From: "101" <sip:101@tenant.domain.com>;tag=vgKr1a4g53H7g
To: <sip:100@192.168.1.73:46139;transport=tls>
Call-ID: 0421387a-0232-123a-2885-f23c92d91233
CSeq: 33462936 INVITE
Contact: <sip:mod_sofia@x.x.x.x:36001;transport=tls>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 120;refresher=uac
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 1491
X-FS-Support: update_display,send_info
Remote-Party-ID: "101" <sip:101@tenant.domain.com>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1616004852 1616004853 IN IP4 50.116.25.52
s=FreeSWITCH
c=IN IP4 50.116.25.52
t=0 0
m=audio 28604 RTP/SAVP 9 0 8 101 13
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-16
a=rtpmap:13 CN/8000
a=crypto:1 AEAD_AES_256_GCM_8 inline:vqP3xupr+Wa+CiDQCrmmtuwb0TMHEJZI4jtWjGO5FVudL7JL1g00HrNZKK0=
a=crypto:2 AEAD_AES_256_GCM inline:oV9BWhXwJGAmP+YDHymtbmWb6BsROp7yybz5U2kaD2pjKGrQ8wGY2tZ3EMc=
a=crypto:3 AEAD_AES_128_GCM_8 inline:+sJ0zEQZafrM7itudsyxbhSeUsFqkAOrJBqTdw==
a=crypto:4 AEAD_AES_128_GCM inline:Rc9hj51P660OwYLguOXYz0B9ibasxBDbLfcFBA==
a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:/0UYeq1TYp3TLEYMqK/wFQuLFo5F1/hDigWQtjOU2n9pmksP5F6mboLs90X/CQ==
a=crypto:6 AES_192_CM_HMAC_SHA1_80 inline:b3Is8FG4t/ig2mq1AvlWyeLozOv8jFVcK6WdsJWyrLvqiQ/7VsQ=
a=crypto:7 AES_CM_128_HMAC_SHA1_80 inline:sCYK/N0mOq44qNGFy/UU1Dhn63BLMlyS7WSelKXv
a=crypto:8 AES_256_CM_HMAC_SHA1_32 inline:H3fsri+KZD85vr/XgwCCiROrF5wN8FAnsIkD1L1kQy7HhR2LzBpurdeTFK21DA==
a=crypto:9 AES_192_CM_HMAC_SHA1_32 inline:/XK/myYVE7z8BLIIH4TEs5zanUnGoZQGlN5CFa83E3Pep7AtZoI=
a=crypto:10 AES_CM_128_HMAC_SHA1_32 inline:R2bMv2RkbDb0GZfSZOXH29NV2v0AaycFb/wEa16I
a=crypto:11 AES_CM_128_NULL_AUTH inline:9tn1298Lw6/ifG1KEgGCRq6xRNkC26ew+Hzq3HK1
a=ptime:20
m=audio 28604 RTP/AVP 9 0 8 101 13
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-16
a=rtpmap:13 CN/8000
a=ptime:20


Code: 
SIP/2.0 400 Bad Request
Via: SIP/2.0/TLS x.x.x.x:36001;rport;branch=z9hG4bKB9KHHS88ZZK2K
From: "101" <sip:101@tenant.domain.com>;tag=vgKr1a4g53H7g
To: <sip:100@192.168.1.73:46139;transport=tls>;tag=F06CD20F-2809E2D4
CSeq: 33462936 INVITE
Call-ID: 0421387a-0232-123a-2885-f23c92d91233
User-Agent: PolycomVVX-VVX_400-UA/5.9.6.2327
Accept-Language: en
Content-Length: 0
 
P

pbxgeek

Active Member
Jan 19, 2021
183
64
28
37
Here is a full log of the call.
Code: 
2021-03-18 14:12:48.921992 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/101@tenant.domain.com [1ffa80d4-38e1-4a8d-8512-115af151345e]
2021-03-18 14:12:48.921992 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/101@tenant.domain.com) Running State Change CS_NEW (Cur 1 Tot 5)
2021-03-18 14:12:48.921992 [DEBUG] sofia.c:10280 sofia/internal/101@tenant.domain.com receiving invite from x.x.x.x:63562 version: 1.10.5 -release-17-25569c1631 64bit
2021-03-18 14:12:48.921992 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port x.x.x.x:0.
2021-03-18 14:12:48.921992 [DEBUG] sofia.c:2434 detaching session 1ffa80d4-38e1-4a8d-8512-115af151345e
2021-03-18 14:12:48.921992 [WARNING] sofia_reg.c:1794 SIP auth challenge (INVITE) on sofia profile 'internal' for [100@tenant.domain.com] from ip x.x.x.x
2021-03-18 14:12:48.921992 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/101@tenant.domain.com) State NEW
2021-03-18 14:12:49.041986 [DEBUG] sofia.c:2544 Re-attaching to session 1ffa80d4-38e1-4a8d-8512-115af151345e
2021-03-18 14:12:49.041986 [DEBUG] sofia.c:10280 sofia/internal/101@tenant.domain.com receiving invite from x.x.x.x:63562 version: 1.10.5 -release-17-25569c1631 64bit
2021-03-18 14:12:49.041986 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port x.x.x.x:0.
2021-03-18 14:12:49.041986 [DEBUG] sofia.c:11477 Setting NAT mode based on via received
2021-03-18 14:12:49.041986 [DEBUG] sofia.c:7326 Channel sofia/internal/101@tenant.domain.com entering state [received][100]
2021-03-18 14:12:49.041986 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=- 1616076769 1616076769 IN IP4 192.168.1.74
s=Polycom IP Phone
c=IN IP4 192.168.1.74
t=0 0
a=sendrecv
m=audio 2236 RTP/SAVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:127 telephone-event/8000
a=crypto:8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c
m=audio 2236 RTP/AVP 9 102 0 8 18 127
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:127 telephone-event/8000

2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AEAD_AES_256_GCM]alias=[] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AEAD_AES_128_GCM]alias=[] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1815 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1824 Found suite AES_CM_128_HMAC_SHA1_80
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1894 Set Remote Key [8 AES_CM_128_HMAC_SHA1_80 inline:1AiugQhwhb/TlAaoOgn2pF3uIiUOuBZLBJtAxB7c]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [8 AES_CM_128_HMAC_SHA1_80 inline:P9oHg/JDAdDC/TjdMy+96/ESSllJaeBIJfgxBq1z]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-03-18 14:12:49.041986 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 127@8000
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/101@tenant.domain.com G722/8000 20 ms 160 samples 64000 bits 1 channels
2021-03-18 14:12:49.061988 [DEBUG] switch_core_codec.c:111 sofia/internal/101@tenant.domain.com Original read codec set to G722:9
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 127@8000
2021-03-18 14:12:49.061988 [DEBUG] switch_core_media.c:5911 sofia/internal/101@tenant.domain.com Set 2833 dtmf send payload to 127 recv payload to 127
2021-03-18 14:12:49.061988 [DEBUG] sofia.c:7760 (sofia/internal/101@tenant.domain.com) State Change CS_NEW -> CS_INIT
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/101@tenant.domain.com) Running State Change CS_INIT (Cur 1 Tot 5)
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/101@tenant.domain.com) State INIT
2021-03-18 14:12:49.061988 [DEBUG] mod_sofia.c:93 sofia/internal/101@tenant.domain.com SOFIA INIT
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:40 sofia/internal/101@tenant.domain.com Standard INIT
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/101@tenant.domain.com) State Change CS_INIT -> CS_ROUTING
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/101@tenant.domain.com) State INIT going to sleep
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/101@tenant.domain.com) Running State Change CS_ROUTING (Cur 1 Tot 5)
2021-03-18 14:12:49.061988 [DEBUG] switch_channel.c:2332 (sofia/internal/101@tenant.domain.com) Callstate Change DOWN -> RINGING
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/101@tenant.domain.com) State ROUTING
2021-03-18 14:12:49.061988 [DEBUG] mod_sofia.c:154 sofia/internal/101@tenant.domain.com SOFIA ROUTING
2021-03-18 14:12:49.061988 [DEBUG] switch_core_state_machine.c:236 sofia/internal/101@tenant.domain.com Standard ROUTING
2021-03-18 14:12:49.061988 [INFO] mod_dialplan_xml.c:637 Processing 101 <101>->100 in context tenant.domain.com
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->user_exists] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(user_exists=true)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [user_exists]=[true]
Dialplan: sofia/internal/101@tenant.domain.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(from_user_exists=true)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [from_user_exists]=[true]
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(extension_uuid=24b7b81a-1c6b-43db-9a37-5a0ae177f44b)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [extension_uuid]=[24b7b81a-1c6b-43db-9a37-5a0ae177f44b]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_all_enabled=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_all_destination=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_busy_enabled=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_busy_enabled]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_busy_destination=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_no_answer_enabled=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_no_answer_enabled]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_no_answer_destination=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_user_not_registered_enabled=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_user_not_registered_enabled]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_user_not_registered_destination=)
2021-03-18 14:12:49.083106 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(forward_all_enabled=)
2021-03-18 14:12:49.121985 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(follow_me_enabled=${user_data ${destination_number}@${domain_name} var follow_me_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(follow_me_enabled=)
2021-03-18 14:12:49.121985 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [follow_me_enabled]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(do_not_disturb=)
2021-03-18 14:12:49.121985 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [do_not_disturb]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(call_timeout=30)
2021-03-18 14:12:49.121985 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [call_timeout]=[30]
Dialplan: sofia/internal/101@tenant.domain.com Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(missed_call_app=)
2021-03-18 14:12:49.121985 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(missed_call_data=)
2021-03-18 14:12:49.121985 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(toll_allow=)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [toll_allow]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(call_screen_enabled=false)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [call_screen_enabled]=[false]
Dialplan: sofia/internal/101@tenant.domain.com Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(user_record=)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [user_record]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call-direction] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com export(call_direction=local)
2021-03-18 14:12:49.141990 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->caller-details] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(caller_destination=100)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [caller_destination]=[100]
Dialplan: sofia/internal/101@tenant.domain.com Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(caller_id_name=101)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [caller_id_name]=[101]
Dialplan: sofia/internal/101@tenant.domain.com Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->global-variables] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->domain-variables] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/101@tenant.domain.com Action set(default_outbound_caller_id_number=3109292680) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(default_outbound_caller_id_number=3109292680)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [default_outbound_caller_id_number]=[3109292680]
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->is_loopback] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->user_record] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(from_user_record=)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [from_user_record]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->rtp_has_crypto] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [rtp_has_crypto] ${rtp_has_crypto}(AES_CM_128_HMAC_SHA1_80) =~ /^(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/101@tenant.domain.com Action set(rtp_secure_media=optional) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(rtp_secure_media=optional)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [rtp_secure_media]=[optional]
Dialplan: sofia/internal/101@tenant.domain.com Action export(rtp_secure_media=optional) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com export(rtp_secure_media=optional)
2021-03-18 14:12:49.141990 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [rtp_secure_media]=[optional]
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->redial] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [redial] destination_number(100) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/101@tenant.domain.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->speed_dial] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [speed_dial] destination_number(100) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->user_hold_music] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [user_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [user_hold_music] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(hold_music=)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [hold_music]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->default_caller_id] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(emergency_caller_id_name=)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(emergency_caller_id_number=)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(3109292680) =~ /^$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->USA_Long_Distance_Peerless1->Thinq->Peerless2] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [USA_Long_Distance_Peerless1->Thinq->Peerless2] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->thinq.011.9-17d] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [thinq.011.9-17d] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->USA_Long_Distance_Thinq->Peerless1->Peerless2] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [USA_Long_Distance_Thinq->Peerless1->Peerless2] ${user_exists}(true) =~ /false/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->Test] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [Test] destination_number(100) =~ /^400$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->agent_status] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [agent_status] destination_number(100) =~ /^\*22$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [agent_status] destination_number(100) =~ /^(agent\+)(.*)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->agent_status_id] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [agent_status_id] destination_number(100) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->group-intercept] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [group-intercept] destination_number(100) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->page-extension] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [page-extension] destination_number(100) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->eavesdrop] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [eavesdrop] destination_number(100) =~ /^\*33(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call_privacy] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call_privacy] destination_number(100) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call_return] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call_return] destination_number(100) =~ /^\*69$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->extension_queue] continue=
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [extension_queue] destination_number(100) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [intercept-ext-polycom] destination_number(100) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->intercept-ext] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [intercept-ext] destination_number(100) =~ /^\*\*(\d+)$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [intercept-ext] destination_number(100) =~ /^\*\*$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->dx] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [dx] destination_number(100) =~ /^dx$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->send_to_voicemail] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [send_to_voicemail] destination_number(100) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->extension-to-voicemail] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [extension-to-voicemail] username(101) =~ /^101$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [extension-to-voicemail] destination_number(100) =~ /^101$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->att_xfer] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [att_xfer] destination_number(100) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->vmain] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [vmain] destination_number(100) =~ /^vmain$|^\*4000$|^\*98$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [vmain] destination_number(100) =~ /^(vmain$|^\*4000$|^\*98)(\d{2,12})$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->xfer_vm] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [xfer_vm] destination_number(100) =~ /^xfer_vm$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->is_transfer] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [is_transfer] destination_number(100) =~ /^is_transfer$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->vmain_user] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [vmain_user] destination_number(100) =~ /^\*97$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->cf] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [cf] destination_number(100) =~ /^cf$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->delay_echo] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [delay_echo] destination_number(100) =~ /^\*9195$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->echo] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [echo] destination_number(100) =~ /^\*9196$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->is_zrtp_secure] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [is_zrtp_secure] ${zrtp_secure_media_confirmed}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com ANTI-Action eval(not_secure)
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->milliwatt] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [milliwatt] destination_number(100) =~ /^\*9197$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->is_secure] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [is_secure] ${sip_via_protocol}(tls) =~ /tls/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [is_secure] ${sip_secure_media_confirmed}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com ANTI-Action eval(not_secure)
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->tone_stream] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [tone_stream] destination_number(100) =~ /^\*9198$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->hold_music] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [hold_music] destination_number(100) =~ /^\*9664$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->recordings] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [recordings] destination_number(100) =~ /^\*(732)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->directory] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [directory] destination_number(100) =~ /^\*411$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->wake-up] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [wake-up] destination_number(100) =~ /^\*(925)$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->valet_park] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [valet_park] destination_number(100) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [valet_park] ${sip_h_Referred-By}() =~ /sip:(.*)@.*/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [valet_park] destination_number(100) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=never
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [valet_park] destination_number(100) =~ /^(park\+)?\*(59[0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->operator] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [operator] destination_number(100) =~ /^0$|^operator$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->operator-forward] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [operator-forward] destination_number(100) =~ /^\*000$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->do-not-disturb] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [do-not-disturb] destination_number(100) =~ /^\*77$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [do-not-disturb] destination_number(100) =~ /^\*78$|\*363$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [do-not-disturb] destination_number(100) =~ /^\*79$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [do-not-disturb] destination_number(100) =~ /^dnd\+101$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call_screen] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call_screen] ${call_screen_enabled}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->follow-me-destinations] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [follow-me-destinations] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [follow-me-destinations] ${follow_me_enabled}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call-forward] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-forward] destination_number(100) =~ /^\*72(\d*)$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-forward] destination_number(100) =~ /^\*73$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-forward] destination_number(100) =~ /^\*74$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-forward] destination_number(100) =~ /^forward\+(\Q101\E)(?:\/(\d+))?$/ break=on-true
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call-forward-all] continue=
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [call-forward-all] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-forward-all] ${forward_all_enabled}() =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->call-forward-not-registered] continue=
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [call-forward-not-registered] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [call-forward-not-registered] ${forward_user_not_registered_enabled}() =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->follow-me] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [follow-me] destination_number(100) =~ /^\*21$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->talking clock date and time] continue=
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [talking clock date and time] destination_number(100) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->talking clock time] continue=
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [talking clock time] destination_number(100) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->talking clock date] continue=
Dialplan: sofia/internal/101@tenant.domain.com Regex (FAIL) [talking clock date] destination_number(100) =~ /^\*9171$/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->local_extension] continue=true
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action export(dialed_extension=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com export(dialed_extension=100)
2021-03-18 14:12:49.141990 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [dialed_extension]=[100]
Dialplan: sofia/internal/101@tenant.domain.com Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
Dialplan: sofia/internal/101@tenant.domain.com Action log(LOG: ${sip_via_protocol} RTP: ${rtp_secure_media_confirmed})
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [local_extension] () =~ // break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/101@tenant.domain.com Action set(continue_on_fail=true)
Dialplan: sofia/internal/101@tenant.domain.com Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/101@tenant.domain.com Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/101@tenant.domain.com Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/internal/101@tenant.domain.com Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/101@tenant.domain.com Action set(api_hangup_hook=lua app.lua hangup)
Dialplan: sofia/internal/101@tenant.domain.com Action export(domain_name=${domain_name})
Dialplan: sofia/internal/101@tenant.domain.com Action bridge(user/${destination_number}@${domain_name})
Dialplan: sofia/internal/101@tenant.domain.com Action lua(app.lua failure_handler)
Dialplan: sofia/internal/101@tenant.domain.com parsing [tenant.domain.com->voicemail] continue=false
Dialplan: sofia/internal/101@tenant.domain.com Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/101@tenant.domain.com Action set(record_append=false) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(record_append=false)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [record_append]=[false]
Dialplan: sofia/internal/101@tenant.domain.com Action set(voicemail_action=save) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(voicemail_action=save)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [voicemail_action]=[save]
Dialplan: sofia/internal/101@tenant.domain.com Action set(voicemail_id=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(voicemail_id=100)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [voicemail_id]=[100]
Dialplan: sofia/internal/101@tenant.domain.com Action set(voicemail_profile=default) INLINE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(voicemail_profile=default)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [voicemail_profile]=[default]
Dialplan: sofia/internal/101@tenant.domain.com Action lua(app.lua voicemail)
2021-03-18 14:12:49.141990 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/101@tenant.domain.com) State Change CS_ROUTING -> CS_EXECUTE
2021-03-18 14:12:49.141990 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/101@tenant.domain.com) State ROUTING going to sleep
2021-03-18 14:12:49.141990 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/101@tenant.domain.com) Running State Change CS_EXECUTE (Cur 1 Tot 5)
2021-03-18 14:12:49.141990 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/101@tenant.domain.com) State EXECUTE
2021-03-18 14:12:49.141990 [DEBUG] mod_sofia.c:209 sofia/internal/101@tenant.domain.com SOFIA EXECUTE
2021-03-18 14:12:49.141990 [DEBUG] switch_core_state_machine.c:329 sofia/internal/101@tenant.domain.com Standard EXECUTE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(caller_id_number=101)
2021-03-18 14:12:49.141990 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [caller_id_number]=[101]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(RFC2822_DATE=Thu, 18 Mar 2021 14:12:49 +0000)
2021-03-18 14:12:49.161986 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [RFC2822_DATE]=[Thu, 18 Mar 2021 14:12:49 +0000]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com export(origination_callee_id_name=100)
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[100]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com hash(insert/tenant.domain.com-last_dial/101/100)
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com eval(not_secure)
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com eval(not_secure)
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com limit(hash tenant.domain.com 100 5 error/user_busy)
2021-03-18 14:12:49.161986 [DEBUG] switch_limit.c:124 incr called: tenant.domain.com_100 max:5, interval:0
2021-03-18 14:12:49.161986 [DEBUG] mod_hash.c:196 Usage for tenant.domain.com_100 is now 1/5
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com log(LOG: tls RTP: )
2021-03-18 14:12:49.161986 [DEBUG] mod_dptools.c:1866 tls RTP:
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(hangup_after_bridge=true)
2021-03-18 14:12:49.161986 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(continue_on_fail=true)
2021-03-18 14:12:49.161986 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com hash(insert/tenant.domain.com-call_return/100/101)
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com hash(insert/tenant.domain.com-last_dial_ext/100/1ffa80d4-38e1-4a8d-8512-115af151345e)
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(called_party_call_group=)
2021-03-18 14:12:49.161986 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [called_party_call_group]=[UNDEF]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com hash(insert/tenant.domain.com-last_dial//1ffa80d4-38e1-4a8d-8512-115af151345e)
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com set(api_hangup_hook=lua app.lua hangup)
2021-03-18 14:12:49.161986 [DEBUG] mod_dptools.c:1672 SET sofia/internal/101@tenant.domain.com [api_hangup_hook]=[lua app.lua hangup]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com export(domain_name=tenant.domain.com)
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [domain_name]=[tenant.domain.com]
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com bridge(user/100@tenant.domain.com)
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [domain_name]=[tenant.domain.com] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [call_direction]=[local] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [rtp_secure_media]=[optional] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [dialed_extension]=[100] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [origination_callee_id_name]=[100] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [domain_name]=[tenant.domain.com] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [domain_name]=[tenant.domain.com] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [call_direction]=[local] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [rtp_secure_media]=[optional] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [dialed_extension]=[100] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [origination_callee_id_name]=[100] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_channel.c:1264 sofia/internal/101@tenant.domain.com EXPORTING[export_vars] [domain_name]=[tenant.domain.com] to event
2021-03-18 14:12:49.161986 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2021-03-18 14:12:49.161986 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/100@192.168.1.73:46139 [80fbd792-9ed6-46d6-8fd2-450a38c64a92]
2021-03-18 14:12:49.161986 [DEBUG] mod_sofia.c:5089 (sofia/internal/100@192.168.1.73:46139) State Change CS_NEW -> CS_INIT
2021-03-18 14:12:49.161986 [DEBUG] switch_ivr_originate.c:3111 sofia/internal/100@192.168.1.73:46139 Setting leg timeout to 30
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.1.73:46139) Running State Change CS_INIT (Cur 2 Tot 6)
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/100@192.168.1.73:46139) State INIT
2021-03-18 14:12:49.161986 [DEBUG] mod_sofia.c:93 sofia/internal/100@192.168.1.73:46139 SOFIA INIT
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [1 AEAD_AES_256_GCM_8 inline:YQPCKLo0OGu3vNZWaOB+fsTqWYgfM6EehqwatyFNK6jKH/mI6wWh/tHlwes=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [1 AEAD_AES_256_GCM_8 inline:gXYiJsrMt5aKjCmOQXuzmbPvMBU9lnMQAdN565WqPDaqX3It7MR/LGkEVMA=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [1 AEAD_AES_256_GCM_8 inline:DJpCA1cTeqhALlHgL/RCe4qWDAn2ibesWwx6VDEJb6TfAoeNRTaGSrHLpv4=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [2 AEAD_AES_256_GCM inline:GGek+akg1sA+SexRlFn7/hStgjEYEXQr4a5aVGxO7ow5B9AhxCfOJ01J484=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [2 AEAD_AES_256_GCM inline:MV6hBnJM/Yyjm7OawmbSBXHj6EK4QVuoAFNZXA+Zf+gnu1ky84h90MFyukU=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [2 AEAD_AES_256_GCM inline:f37nDOimd5IyKmNKBJ9n2WZe4e5lHsib8AdyuHnYFyaPAJbsWNSMEWt9pMs=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [3 AEAD_AES_128_GCM_8 inline:KqZ7FsT3RGQUqqFUPPVpmBV2X9wRVqgoK4fHvg==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [3 AEAD_AES_128_GCM_8 inline:uRx5vwq0ZMQXbhaofutleMr4hwkApaYTwXRK4w==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [3 AEAD_AES_128_GCM_8 inline:/G34rM07fCvjpSeYMga04qxS9eB9Db3/nKIoFg==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [4 AEAD_AES_128_GCM inline:t/9iPc5W9LWyk9vsKYERntoiGQgTXK2RPuafwg==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [4 AEAD_AES_128_GCM inline:mGQp6vRMYnoVOW8ir3PL/1hRcZpksJD/z+tsPw==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [4 AEAD_AES_128_GCM inline:PeBuTj47qnge2QcgqLnuduP2zeSfnagEa5PZUQ==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [5 AES_256_CM_HMAC_SHA1_80 inline:pyx6IM7sEfwBcEw5DoUiln2UDLN2LNJMbhAodcGtR9JW0cMshaytM/TsbKOhNA==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [5 AES_256_CM_HMAC_SHA1_80 inline:CbtfqWi4P6DHiIMjIBZMnnJjG5qAZbEKVlbWpglhwtpK7QClchkX40crZSrrCw==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [5 AES_256_CM_HMAC_SHA1_80 inline:nNcqnDL/Jxvs6k0+6pgo8FioCE7RlvB++NnyEl7/hYayormwAEFu8cMTtt38gA==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [6 AES_192_CM_HMAC_SHA1_80 inline:ydHFt1W1yqSMoDkAtvgdVMYtKD0ysLlPraHkCRjOatUXvWNpEEg=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [6 AES_192_CM_HMAC_SHA1_80 inline:B9nLJc2t/B00uHvn/ImuMFTErF00twb48vZnh0XVd0VoLCJX6XM=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [6 AES_192_CM_HMAC_SHA1_80 inline:Z4m0yaAdq+TgwLDonBWa08yMi51AcLvREe9/b/hAwgcsSxBK4mE=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [7 AES_CM_128_HMAC_SHA1_80 inline:E+kCsCg8OjcF7uVZtn17MsFSXqA6pNBwIeXO+2S7]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [7 AES_CM_128_HMAC_SHA1_80 inline:9bCa9xCehv8q6QF7OYgZZGNs8I2EY1bq8zCzKJmD]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [7 AES_CM_128_HMAC_SHA1_80 inline:/w1ETxYNOEHny7AipiHq7zh5xkv5ns5brc2yE26a]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [8 AES_256_CM_HMAC_SHA1_32 inline:XRvhnX++HJNj254sH2EX73jgBp4D0K4H/qtn4u8L3mcYHF0esRDk7p42nXZtPw==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [8 AES_256_CM_HMAC_SHA1_32 inline:BuRJ7vKeSVlaGnknz3sh4tbdfog+12woYFW/wmBnEj56PhpjwnvH6qLp3NzC1g==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [8 AES_256_CM_HMAC_SHA1_32 inline:IxTa/Tm/RKUnh/SxNZci7Q1CFJbGz/BwNkYenwKAktk1+eVJVHpo+QxQO2wG+A==]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [9 AES_192_CM_HMAC_SHA1_32 inline:Djuh0JweS3gwZX7UHNSYdH3OuJ2WLdOAv8zqlRMR8UDcUs0I/tw=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [9 AES_192_CM_HMAC_SHA1_32 inline:mIfHCPTHdBRD4NCFmXmiJxZIdwLZQzGY81PNeTdjtEZWTeaQbOA=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [9 AES_192_CM_HMAC_SHA1_32 inline:YNBZo2R5Qmcd164E24wDHQjwajoOF54jPJkGqs0+MDtJQP/jwUg=]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [10 AES_CM_128_HMAC_SHA1_32 inline:sFOt7RjDSm4WoSuAw0GgFUPdm5/ktdlIP4pQ+ON/]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [10 AES_CM_128_HMAC_SHA1_32 inline:cDn+CqBKF/5MHwMrsHbUvSqdi/yHRDXxqUJH9ZxA]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [10 AES_CM_128_HMAC_SHA1_32 inline:BjwvWSH2O69uCUFiaz6h2cXMQgW83i1BGONStW/Y]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local audio crypto Key [11 AES_CM_128_NULL_AUTH inline:k0rfkbQBeXxJeTVZviwz/0edaYyLaKcPRCZhK0ik]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local video crypto Key [11 AES_CM_128_NULL_AUTH inline:P/7N0lVGV5vAvHRrvgfrcjFruYO0Lk9keN+pTKSw]
2021-03-18 14:12:49.161986 [DEBUG] switch_core_media.c:1217 Set Local text crypto Key [11 AES_CM_128_NULL_AUTH inline:kbnzm1H2Lp3pafWAiz4V+oCgd8BEWq3neqXKRC5Z]
2021-03-18 14:12:49.161986 [DEBUG] sofia_glue.c:1587 sip:100@x.x.x.x:46139;transport=tls Setting proxy route to sofia/internal/100@192.168.1.73:46139
2021-03-18 14:12:49.161986 [DEBUG] sofia_glue.c:1618 sofia/internal/100@192.168.1.73:46139 sending invite version: 1.10.5 -release-17-25569c1631 64bit
Local SDP:
v=0
o=FreeSWITCH 1616047489 1616047490 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 29280 RTP/SAVP 9 0 8 101 13
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-16
a=crypto:1 AEAD_AES_256_GCM_8 inline:YQPCKLo0OGu3vNZWaOB+fsTqWYgfM6EehqwatyFNK6jKH/mI6wWh/tHlwes=
a=crypto:2 AEAD_AES_256_GCM inline:GGek+akg1sA+SexRlFn7/hStgjEYEXQr4a5aVGxO7ow5B9AhxCfOJ01J484=
a=crypto:3 AEAD_AES_128_GCM_8 inline:KqZ7FsT3RGQUqqFUPPVpmBV2X9wRVqgoK4fHvg==
a=crypto:4 AEAD_AES_128_GCM inline:t/9iPc5W9LWyk9vsKYERntoiGQgTXK2RPuafwg==
a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:pyx6IM7sEfwBcEw5DoUiln2UDLN2LNJMbhAodcGtR9JW0cMshaytM/TsbKOhNA==
a=crypto:6 AES_192_CM_HMAC_SHA1_80 inline:ydHFt1W1yqSMoDkAtvgdVMYtKD0ysLlPraHkCRjOatUXvWNpEEg=
a=crypto:7 AES_CM_128_HMAC_SHA1_80 inline:E+kCsCg8OjcF7uVZtn17MsFSXqA6pNBwIeXO+2S7
a=crypto:8 AES_256_CM_HMAC_SHA1_32 inline:XRvhnX++HJNj254sH2EX73jgBp4D0K4H/qtn4u8L3mcYHF0esRDk7p42nXZtPw==
a=crypto:9 AES_192_CM_HMAC_SHA1_32 inline:Djuh0JweS3gwZX7UHNSYdH3OuJ2WLdOAv8zqlRMR8UDcUs0I/tw=
a=crypto:10 AES_CM_128_HMAC_SHA1_32 inline:sFOt7RjDSm4WoSuAw0GgFUPdm5/ktdlIP4pQ+ON/
a=crypto:11 AES_CM_128_NULL_AUTH inline:k0rfkbQBeXxJeTVZviwz/0edaYyLaKcPRCZhK0ik
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
m=audio 29280 RTP/AVP 9 0 8 101 13
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-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100@192.168.1.73:46139 Standard INIT
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100@192.168.1.73:46139) State Change CS_INIT -> CS_ROUTING
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/100@192.168.1.73:46139) State INIT going to sleep
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.1.73:46139) Running State Change CS_ROUTING (Cur 2 Tot 6)
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/100@192.168.1.73:46139) State ROUTING
2021-03-18 14:12:49.161986 [DEBUG] mod_sofia.c:154 sofia/internal/100@192.168.1.73:46139 SOFIA ROUTING
2021-03-18 14:12:49.161986 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/100@192.168.1.73:46139) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/100@192.168.1.73:46139) State ROUTING going to sleep
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.1.73:46139) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 6)
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/100@192.168.1.73:46139) State CONSUME_MEDIA
2021-03-18 14:12:49.161986 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/100@192.168.1.73:46139) State CONSUME_MEDIA going to sleep
2021-03-18 14:12:49.161986 [DEBUG] sofia.c:7326 Channel sofia/internal/100@192.168.1.73:46139 entering state [calling][0]
2021-03-18 14:12:49.262000 [DEBUG] sofia.c:7326 Channel sofia/internal/100@192.168.1.73:46139 entering state [terminated][400]
2021-03-18 14:12:49.262000 [NOTICE] sofia.c:8559 Hangup sofia/internal/100@192.168.1.73:46139 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.1.73:46139) Running State Change CS_HANGUP (Cur 2 Tot 6)
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/100@192.168.1.73:46139) Callstate Change DOWN -> HANGUP
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100@192.168.1.73:46139) State HANGUP
2021-03-18 14:12:49.262000 [DEBUG] mod_sofia.c:453 Channel sofia/internal/100@192.168.1.73:46139 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100@192.168.1.73:46139 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100@192.168.1.73:46139) State HANGUP going to sleep
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/100@192.168.1.73:46139) State Change CS_HANGUP -> CS_REPORTING
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.1.73:46139) Running State Change CS_REPORTING (Cur 2 Tot 6)
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/100@192.168.1.73:46139) State REPORTING
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100@192.168.1.73:46139 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/100@192.168.1.73:46139) State REPORTING going to sleep
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/100@192.168.1.73:46139) State Change CS_REPORTING -> CS_DESTROY
2021-03-18 14:12:49.262000 [DEBUG] switch_core_session.c:1726 Session 6 (sofia/internal/100@192.168.1.73:46139) Locked, Waiting on external entities
2021-03-18 14:12:49.262000 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2021-03-18 14:12:49.262000 [NOTICE] switch_core_session.c:1744 Session 6 (sofia/internal/100@192.168.1.73:46139) Ended
2021-03-18 14:12:49.262000 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/100@192.168.1.73:46139 [CS_DESTROY]
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/100@192.168.1.73:46139) Running State Change CS_DESTROY (Cur 1 Tot 6)
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/100@192.168.1.73:46139) State DESTROY
2021-03-18 14:12:49.262000 [DEBUG] mod_sofia.c:364 sofia/internal/100@192.168.1.73:46139 SOFIA DESTROY
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100@192.168.1.73:46139 Standard DESTROY
2021-03-18 14:12:49.262000 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/100@192.168.1.73:46139) State DESTROY going to sleep
2021-03-18 14:12:49.262000 [NOTICE] switch_ivr_originate.c:2999 Cannot create outgoing channel of type [user] cause: [NORMAL_TEMPORARY_FAILURE]
2021-03-18 14:12:49.262000 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2021-03-18 14:12:49.262000 [INFO] mod_dptools.c:3631 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com lua(app.lua failure_handler)
2021-03-18 14:12:49.281986 [DEBUG] switch_cpp.cpp:1191 sofia/internal/101@tenant.domain.com destroy/unlink session from object
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com lua(app.lua voicemail)
2021-03-18 14:12:49.302064 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/101@tenant.domain.com] x.x.x.x port 20470 -> 192.168.1.74 port 2236 codec: 9 ms: 20
2021-03-18 14:12:49.302064 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 160 bytes per 20ms
2021-03-18 14:12:49.302064 [DEBUG] switch_core_media.c:8977 sofia/internal/101@tenant.domain.com Set 2833 dtmf send payload to 127
2021-03-18 14:12:49.302064 [DEBUG] switch_core_media.c:8984 sofia/internal/101@tenant.domain.com Set 2833 dtmf receive payload to 127
2021-03-18 14:12:49.302064 [DEBUG] switch_core_media.c:9007 sofia/internal/101@tenant.domain.com Set rtp dtmf delay to 40
2021-03-18 14:12:49.302064 [INFO] switch_rtp.c:4254 Activating audio Secure RTP SEND
2021-03-18 14:12:49.302064 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2021-03-18 14:12:49.302064 [INFO] switch_rtp.c:4232 Activating audio Secure RTP RECV
2021-03-18 14:12:49.302064 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2021-03-18 14:12:49.302064 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/101@tenant.domain.com:
v=0
o=FreeSWITCH 1616056299 1616056300 IN IP4 x.x.x.x
s=FreeSWITCH
c=IN IP4 x.x.x.x
t=0 0
m=audio 20470 RTP/SAVP 9 127
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=ptime:20
a=sendrecv
a=crypto:8 AES_CM_128_HMAC_SHA1_80 inline:P9oHg/JDAdDC/TjdMy+96/ESSllJaeBIJfgxBq1z
m=audio 0 RTP/AVP 19

2021-03-18 14:12:49.302064 [NOTICE] switch_cpp.cpp:685 Channel [sofia/internal/101@tenant.domain.com] has been answered
2021-03-18 14:12:49.302064 [DEBUG] switch_channel.c:3865 (sofia/internal/101@tenant.domain.com) Callstate Change RINGING -> ACTIVE
2021-03-18 14:12:49.302064 [DEBUG] sofia.c:7326 Channel sofia/internal/101@tenant.domain.com entering state [completed][200]
2021-03-18 14:12:49.302064 [DEBUG] switch_ivr.c:195 Codec Activated L16@16000hz 1 channels 20ms
2021-03-18 14:12:49.361986 [DEBUG] sofia.c:7326 Channel sofia/internal/101@tenant.domain.com entering state [ready][200]
2021-03-18 14:12:49.681987 [INFO] switch_rtp.c:7719 Auto Changing audio port from 192.168.1.74:2236 to x.x.x.x:2236
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com unbind_meta_app()
2021-03-18 14:12:50.321986 [INFO] switch_ivr_async.c:4356 UnBound A-Leg: ALL
2021-03-18 14:12:50.321986 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('playback_terminators', '#')
2021-03-18 14:12:50.321986 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('missed_call', 'true')
2021-03-18 14:12:50.321986 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_answer_stamp', '2021-03-18 14:12:50')
2021-03-18 14:12:50.321986 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_answer_epoch', '1616076770')
EXECUTE [depth=0] sofia/internal/101@tenant.domain.com playback(silence_stream://200)
2021-03-18 14:12:50.321986 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2021-03-18 14:12:50.521985 [DEBUG] switch_ivr_play_say.c:1933 done playing file silence_stream://200
2021-03-18 14:12:50.521985 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2021-03-18 14:12:50.542013 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
2021-03-18 14:12:50.542013 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2021-03-18 14:12:51.881984 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
2021-03-18 14:12:51.881984 [DEBUG] switch_ivr.c:195 Codec Activated L16@16000hz 1 channels 20ms
2021-03-18 14:12:52.001982 [DEBUG] switch_ivr_play_say.c:250 Handle say:[100] (en:en)
2021-03-18 14:12:52.001982 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2021-03-18 14:12:52.081979 [NOTICE] sofia.c:1089 Hangup sofia/internal/101@tenant.domain.com [CS_EXECUTE] [NORMAL_CLEARING]
2021-03-18 14:12:52.081979 [DEBUG] mod_hash.c:296 Usage for tenant.domain.com_100 is now 0
2021-03-18 14:12:52.081979 [DEBUG] switch_ivr_play_say.c:1933 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav
2021-03-18 14:12:52.081979 [DEBUG] switch_core_session.c:2685 sofia/internal/101@tenant.domain.com Channel is hungup and application 'playback' does not have the zombie_exec flag.
2021-03-18 14:12:52.101994 [NOTICE] switch_cpp.cpp:1447 [voicemail]
2021-03-18 14:12:52.101994 [DEBUG] switch_cpp.cpp:1191 sofia/internal/101@tenant.domain.com destroy/unlink session from object
2021-03-18 14:12:52.101994 [DEBUG] switch_core_session.c:2905 sofia/internal/101@tenant.domain.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/101@tenant.domain.com) State EXECUTE going to sleep
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/101@tenant.domain.com) Running State Change CS_HANGUP (Cur 1 Tot 6)
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/101@tenant.domain.com) Callstate Change ACTIVE -> HANGUP
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/101@tenant.domain.com) State HANGUP
2021-03-18 14:12:52.101994 [DEBUG] mod_sofia.c:447 sofia/internal/101@tenant.domain.com Overriding SIP cause 480 with 400 from the other leg
2021-03-18 14:12:52.101994 [DEBUG] mod_sofia.c:453 Channel sofia/internal/101@tenant.domain.com hanging up, cause: NORMAL_CLEARING
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:60 sofia/internal/101@tenant.domain.com Standard HANGUP, cause: NORMAL_CLEARING
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/101@tenant.domain.com) State HANGUP going to sleep
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:781 Hangup Command with no Session lua(app.lua hangup):

2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/101@tenant.domain.com) State Change CS_HANGUP -> CS_REPORTING
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/101@tenant.domain.com) Running State Change CS_REPORTING (Cur 1 Tot 6)
2021-03-18 14:12:52.101994 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/101@tenant.domain.com) State REPORTING
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:174 sofia/internal/101@tenant.domain.com Standard REPORTING, cause: NORMAL_CLEARING
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/101@tenant.domain.com) State REPORTING going to sleep
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/101@tenant.domain.com) State Change CS_REPORTING -> CS_DESTROY
2021-03-18 14:12:52.182044 [DEBUG] switch_core_session.c:1726 Session 5 (sofia/internal/101@tenant.domain.com) Locked, Waiting on external entities
2021-03-18 14:12:52.182044 [NOTICE] switch_core_session.c:1744 Session 5 (sofia/internal/101@tenant.domain.com) Ended
2021-03-18 14:12:52.182044 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/101@tenant.domain.com [CS_DESTROY]
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/101@tenant.domain.com) Running State Change CS_DESTROY (Cur 0 Tot 6)
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/101@tenant.domain.com) State DESTROY
2021-03-18 14:12:52.182044 [DEBUG] mod_sofia.c:364 sofia/internal/101@tenant.domain.com SOFIA DESTROY
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:181 sofia/internal/101@tenant.domain.com Standard DESTROY
2021-03-18 14:12:52.182044 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/101@tenant.domain.com) State DESTROY going to sleep
 
P

pbxgeek

Active Member
Jan 19, 2021
183
64
28
37
Turns out the issue was with Polycom phone not validating the backup servers. Security feature and worked by design. Once the phone new about the new server calls started to work
 
Status
Not open for further replies.
Top Bottom