[Freeswitch-dev] Eror: 488 Not Acceptable Here while connecting two JS-SIP clients

Thu Oct 6 10:47:03 UTC 2022

Hi

perfectly agree that there are so many queries to this end and almost all
pointers are towards codec negotiation failures. i still have this issue
after i see that codec negotiation goes through.

i have set up 2 Js-SIP clients. webrtc.
i am able to connect and register both clients (can see those in *sofia
status profile external reg*)

however when i place a call from one client (extension 1000) to another
(extension 1001), i receive a "488 Not Acceptable Here" message and the
call ends with "Bad Media Description" error and i never get the call on
receiver side

i am completely at the surface still and have given it a try with all
solutions posted to this end

attaching the entire log in a file here. please help

here are some important bits from the file:

INVITE sip

INVITE sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
X-Test: tester-tested
Contact: <sip:1000 at 11.22.33.44;ob>
Content-Type: application/sdp
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: ice,replaces,outbound
User-Agent: JsSIP 3.9.1
Content-Length: 1950

v=0
o=- 8689874841498562319 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113
126
c=IN IP4 192.168.1.64
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host
generation 0 network-id 1 network-cost 10
a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host
generation 0 network-id 2 network-cost 50
a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype
active generation 0 network-id 1 network-cost 10
a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype
active generation 0 network-id 2 network-cost 50
a=ice-ufrag:KQsy
a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
a=ice-options:trickle
a=fingerprint:sha-256
C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3
http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=sendrecv
a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:63 red/48000/2
a=fmtp:63 111/111
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2

=================

Remote SDP:

2022-10-06 10:18:15.078122 99.83% [NOTICE] switch_channel.c:1123 New
Channel sofia/external/1000 at 11.22.33.44 []
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581
(sofia/external/1000 at 11.22.33.44) Running State Change CS_NEW (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [INFO] sofia.c:10465 sofia/external/
1000 at 11.22.33.44 receiving invite from 3.7.130.46:54985 version: 1.10.8-dev
git 98d2e62 2022-09-09 13:32:35Z 64bit call-id: aoc0tkcjs47mrj5n1jl4
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:11674 Setting NAT mode
based on websockets
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7499 Channel
sofia/external/1000 at 11.22.33.44 entering state [received][100]
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7509 Remote SDP:
 v=0
 o=- 8689874841498562319 2 IN IP4 127.0.0.1
 s=-
 t=0 0
 a=group:BUNDLE 0
 a=extmap-allow-mixed
 a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
 m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112
113 126
 c=IN IP4 192.168.1.64
 a=rtpmap:111 opus/48000/2
 a=fmtp:111 minptime=10;useinbandfec=1
 a=rtpmap:63 red/48000/2
 a=fmtp:63 111/111
 a=rtpmap:103 ISAC/16000
 a=rtpmap:104 ISAC/32000
 a=rtpmap:9 G722/8000
 a=rtpmap:0 PCMU/8000
 a=rtpmap:8 PCMA/8000
 a=rtpmap:106 CN/32000
 a=rtpmap:105 CN/16000
 a=rtpmap:13 CN/8000
 a=rtpmap:110 telephone-event/48000
 a=rtpmap:112 telephone-event/32000
 a=rtpmap:113 telephone-event/16000
 a=rtpmap:126 telephone-event/8000
 a=rtcp:9 IN IP4 0.0.0.0
 a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host
generation 0 network-id 1 network-cost 10
 a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host
generation 0 network-id 2 network-cost 50
 a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype
active generation 0 network-id 1 network-cost 10
 a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype
active generation 0 network-id 2 network-cost 50
 a=ice-ufrag:KQsy
 a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
 a=ice-options:trickle
 a=fingerprint:sha-256
C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
 a=setup:actpass
 a=mid:0
 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
 a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
 a=extmap:3
http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
 a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
 a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2
 a=rtcp-mux
 a=rtcp-fb:111 transport-cc
 a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
 a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2

=============================================
codec negotiation. i have removed OPUS as it was giving me bitrate mismatch
*G722, PCMU, PCMA are exact match*

 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [opus:111:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [red:63:48000:20:0:2]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [red:63:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [red:63:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio
Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio
Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio
Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]

=======================================================

SIP to receiver

2022-10-06 10:18:25.018122 99.80% [DEBUG] mod_sofia.c:913 Local SDP
sofia/external/1000 at 11.22.33.44:
 v=0
 o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
 s=FreeSWITCH
 c=IN IP4 11.22.33.44
 t=0 0
 a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
 m=audio 29876 UDP/AVPF 9 126
 a=rtpmap:9 G722/8000
 a=rtpmap:126 telephone-event/8000
 a=ptime:20
 a=sendrecv
 a=rtcp:29877 IN IP4 11.22.33.44
 a=ice-ufrag:0OsMZPPHcIga8KUi
 a=ice-pwd:XaZYj9vC6oyD4TjUxCxnhcUk
 a=candidate:0153546995 1 udp 2130706431 11.22.33.44 29876 typ host
generation 0
 a=candidate:0153546995 2 udp 2130706430 11.22.33.44 29877 typ host
generation 0
 a=end-of-candidates
 a=ssrc:3007569695 cname:kmpRbjjGt625HQuP
 a=ssrc:3007569695 msid:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET a0
 a=ssrc:3007569695 mslabel:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
 a=ssrc:3007569695 label:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zETa0

 2022-10-06 10:18:25.018122 99.80% [NOTICE] mod_dptools.c:1408 Channel
[sofia/external/1000 at 11.22.33.44] has been answered
send 985 bytes to wss/[3.7.130.46]:54985 at 10:18:25.032155:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/WSS
11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
Contact: <sip:1001 at 11.22.33.44:5080;transport=udp>
User-Agent:
FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER,
REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 196
Remote-Party-ID: "1001" <sip:1001 at 11.22.33.44
>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
*m=audio 0 UDP/TLS/RTP/SAVPF 19*

 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_channel.c:3950
(sofia/external/1000 at 11.22.33.44) Callstate Change EARLY -> ACTIVE
 2022-10-06 10:18:25.018122 99.80% [DEBUG] sofia.c:7499 Channel
sofia/external/1000 at 11.22.33.44 entering state [completed][200]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 sleep(1000)

==============================================

and then the BYE

------------------------------------------------------------------------
ACK sip:1001 at 11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK8228266
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

recv 462 bytes from wss/[3.7.130.46]:54985 at 10:18:26.584127:
------------------------------------------------------------------------
BYE sip:1001 at 11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK162798
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3753 BYE
*Reason: SIP ;cause=488; text="Not Acceptable Here"*
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

-- 
Shwetank
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20221006/cc790c7c/attachment-0001.html>
-------------- next part --------------
------------------------------------------------------------------------
NOTIFY sip:1000 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKHmjXXy5mgaQ7e
Route: <sip:1000 at 3.7.130.46:54807>
Max-Forwards: 70
From: <sip:1000 at 11.22.33.44>;tag=XQe15tHe7457D
To: <sip:1000 at 11.22.33.44>
Call-ID: 02d75bac-c003-123b-ee87-0abef6a004ad
CSeq: 57971951 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1000 at 11.22.33.44

send 828 bytes to udp/[3.7.130.46]:54991 at 10:18:14.188356:
------------------------------------------------------------------------
NOTIFY sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKgBS4U3mHK10mK
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 70
From: <sip:1001 at 11.22.33.44>;tag=tv2p09y3Fa3FB
To: <sip:1001 at 11.22.33.44>
Call-ID: fe5e6482-c002-123b-ee87-0abef6a004ad
CSeq: 57971947 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1001 at 11.22.33.44

recv 2439 bytes from wss/[3.7.130.46]:54985 at 10:18:15.078106:
------------------------------------------------------------------------
INVITE sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
X-Test: tester-tested
Contact: <sip:1000 at 11.22.33.44;ob>
Content-Type: application/sdp
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: ice,replaces,outbound
User-Agent: JsSIP 3.9.1
Content-Length: 1950

v=0
o=- 8689874841498562319 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 192.168.1.64
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host generation 0 network-id 1 network-cost 10
a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host generation 0 network-id 2 network-cost 50
a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype active generation 0 network-id 1 network-cost 10
a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype active generation 0 network-id 2 network-cost 50
a=ice-ufrag:KQsy
a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
a=ice-options:trickle
a=fingerprint:sha-256 C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=sendrecv
a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:63 red/48000/2
a=fmtp:63 111/111
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2

 2022-10-06 10:18:15.078122 99.83% [NOTICE] switch_channel.c:1123 New Channel sofia/external/1000 at 11.22.33.44 []
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_NEW (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [INFO] sofia.c:10465 sofia/external/1000 at 11.22.33.44 receiving invite from 3.7.130.46:54985 version: 1.10.8-dev git 98d2e62 2022-09-09 13:32:35Z 64bit call-id: aoc0tkcjs47mrj5n1jl4
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:11674 Setting NAT mode based on websockets
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7499 Channel sofia/external/1000 at 11.22.33.44 entering state [received][100]
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7509 Remote SDP:
 v=0
 o=- 8689874841498562319 2 IN IP4 127.0.0.1
 s=-
 t=0 0
 a=group:BUNDLE 0
 a=extmap-allow-mixed
 a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
 m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113 126
 c=IN IP4 192.168.1.64
 a=rtpmap:111 opus/48000/2
 a=fmtp:111 minptime=10;useinbandfec=1
 a=rtpmap:63 red/48000/2
 a=fmtp:63 111/111
 a=rtpmap:103 ISAC/16000
 a=rtpmap:104 ISAC/32000
 a=rtpmap:9 G722/8000
 a=rtpmap:0 PCMU/8000
 a=rtpmap:8 PCMA/8000
 a=rtpmap:106 CN/32000
 a=rtpmap:105 CN/16000
 a=rtpmap:13 CN/8000
 a=rtpmap:110 telephone-event/48000
 a=rtpmap:112 telephone-event/32000
 a=rtpmap:113 telephone-event/16000
 a=rtpmap:126 telephone-event/8000
 a=rtcp:9 IN IP4 0.0.0.0
 a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host generation 0 network-id 1 network-cost 10
 a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host generation 0 network-id 2 network-cost 50
 a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype active generation 0 network-id 1 network-cost 10
 a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype active generation 0 network-id 2 network-cost 50
 a=ice-ufrag:KQsy
 a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
 a=ice-options:trickle
 a=fingerprint:sha-256 C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
 a=setup:actpass
 a=mid:0
 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
 a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
 a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
 a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
 a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
 a=rtcp-mux
 a=rtcp-fb:111 transport-cc
 a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
 a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2

 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7912 (sofia/external/1000 at 11.22.33.44) State Change CS_NEW -> CS_INIT
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:600 (sofia/external/1000 at 11.22.33.44) State NEW
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_INIT (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:624 (sofia/external/1000 at 11.22.33.44) State INIT
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:97 sofia/external/1000 at 11.22.33.44 SOFIA INIT
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:40 sofia/external/1000 at 11.22.33.44 Standard INIT
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:48 (sofia/external/1000 at 11.22.33.44) State Change CS_INIT -> CS_ROUTING
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:624 (sofia/external/1000 at 11.22.33.44) State INIT going to sleep
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_ROUTING (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:2380 (sofia/external/1000 at 11.22.33.44) Callstate Change DOWN -> RINGING
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1000 at 11.22.33.44) State ROUTING
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:158 sofia/external/1000 at 11.22.33.44 SOFIA ROUTING
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:230 sofia/external/1000 at 11.22.33.44 Standard ROUTING
 2022-10-06 10:18:15.078122 99.83% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->1001 in context public
send 340 bytes to wss/[3.7.130.46]:54985 at 10:18:15.079669:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
To: <sip:1001 at 11.22.33.44>
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Content-Length: 0

 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [public->unloop] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [public->outside_call] continue=true
 Dialplan: sofia/external/1000 at 11.22.33.44 Absolute Condition [outside_call]
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(outside_call=true)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [public->call_debug] continue=true
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [call_debug] ${call_debug}(true) =~ /^true$/ break=never
 Dialplan: sofia/external/1000 at 11.22.33.44 Action info()
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [public->public_extensions] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [public_extensions] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 Action transfer(1001 XML default)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:281 (sofia/external/1000 at 11.22.33.44) State Change CS_ROUTING -> CS_EXECUTE
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1000 at 11.22.33.44) State ROUTING going to sleep
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_EXECUTE (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:647 (sofia/external/1000 at 11.22.33.44) State EXECUTE
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:213 sofia/external/1000 at 11.22.33.44 SOFIA EXECUTE
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:323 sofia/external/1000 at 11.22.33.44 Standard EXECUTE
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(outside_call=true)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [outside_call]=[true]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 export(RFC2822_DATE=Thu, 06 Oct 2022 10:18:15 +0000)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 info()
 2022-10-06 10:18:15.078122 99.83% [INFO] mod_dptools.c:1886 CHANNEL_DATA:
 Channel-State: [CS_EXECUTE]
 Channel-Call-State: [RINGING]
 Channel-State-Number: [4]
 Channel-Name: [sofia/external/1000 at 11.22.33.44]
 Unique-ID: []
 Call-Direction: [inbound]
 Presence-Call-Direction: [inbound]
 Channel-HIT-Dialplan: [true]
 Channel-Call-UUID: []
 Answer-State: [ringing]
 Caller-Direction: [inbound]
 Caller-Logical-Direction: [inbound]
 Caller-Username: [1000]
 Caller-Dialplan: [XML]
 Caller-Caller-ID-Name: [1000]
 Caller-Caller-ID-Number: [1000]
 Caller-Orig-Caller-ID-Name: [1000]
 Caller-Orig-Caller-ID-Number: [1000]
 Caller-Network-Addr: [3.7.130.46]
 Caller-ANI: [1000]
 Caller-Destination-Number: [1001]
 Caller-Unique-ID: []
 Caller-Source: [mod_sofia]
 Caller-Context: [public]
 Caller-Channel-Name: [sofia/external/1000 at 11.22.33.44]
 Caller-Profile-Index: [1]
 Caller-Profile-Created-Time: [1665051495078122]
 Caller-Channel-Created-Time: [1665051495078122]
 Caller-Channel-Answered-Time: [0]
 Caller-Channel-Progress-Time: [0]
 Caller-Channel-Progress-Media-Time: [0]
 Caller-Channel-Hangup-Time: [0]
 Caller-Channel-Transfer-Time: [0]
 Caller-Channel-Resurrect-Time: [0]
 Caller-Channel-Bridged-Time: [0]
 Caller-Channel-Last-Hold: [0]
 Caller-Channel-Hold-Accum: [0]
 Caller-Screen-Bit: [true]
 Caller-Privacy-Hide-Name: [false]
 Caller-Privacy-Hide-Number: [false]
 variable_direction: [inbound]
 variable_uuid: []
 variable_session_id: [11]
 variable_sip_from_user: [1000]
 variable_sip_from_uri: [1000 at 11.22.33.44]
 variable_sip_from_host: [11.22.33.44]
 variable_video_media_flow: [disabled]
 variable_audio_media_flow: [disabled]
 variable_text_media_flow: [disabled]
 variable_channel_name: [sofia/external/1000 at 11.22.33.44]
 variable_sip_call_id: [aoc0tkcjs47mrj5n1jl4]
 variable_sip_local_network_addr: [11.22.33.44]
 variable_sip_network_ip: [3.7.130.46]
 variable_sip_network_port: [54985]
 variable_sip_invite_stamp: [1665051495078122]
 variable_sip_received_ip: [3.7.130.46]
 variable_sip_received_port: [54985]
 variable_sip_via_protocol: [wss]
 variable_sip_from_user_stripped: [1000]
 variable_sip_from_tag: [jimkkm04qn]
 variable_sofia_profile_name: [external]
 variable_sofia_profile_url: [sip:mod_sofia at 11.22.33.44:5080]
 variable_recovery_profile_name: [external]
 variable_sip_full_via: [SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985]
 variable_sip_full_from: [<sip:1000 at 11.22.33.44>;tag=jimkkm04qn]
 variable_sip_full_to: [<sip:1001 at 11.22.33.44>]
 variable_sip_allow: [INVITE, ACK, CANCEL, BYE, UPDATE, MESSAGE, OPTIONS, REFER, INFO, NOTIFY]
 variable_sip_req_user: [1001]
 variable_sip_req_uri: [1001 at 11.22.33.44]
 variable_sip_req_host: [11.22.33.44]
 variable_sip_to_user: [1001]
 variable_sip_to_uri: [1001 at 11.22.33.44]
 variable_sip_to_host: [11.22.33.44]
 variable_sip_contact_params: [ob]
 variable_sip_contact_user: [1000]
 variable_sip_contact_uri: [1000 at 11.22.33.44]
 variable_sip_contact_host: [11.22.33.44]
 variable_rtp_use_codec_string: [G722,PCMU,PCMA]
 variable_sip_user_agent: [JsSIP 3.9.1]
 variable_sip_via_host: [11.22.33.44]
 variable_sip_via_rport: [54985]
 variable_max_forwards: [69]
 variable_sip_h_X-Test: [tester-tested]
 variable_sip_nat_detected: [true]
 variable_switch_r_sdp: [v=0
 o=- 8689874841498562319 2 IN IP4 127.0.0.1
 s=-
 t=0 0
 a=group:BUNDLE 0
 a=extmap-allow-mixed
 a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
 m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113 126
 c=IN IP4 192.168.1.64
 a=rtpmap:111 opus/48000/2
 a=fmtp:111 minptime=10;useinbandfec=1
 a=rtpmap:63 red/48000/2
 a=fmtp:63 111/111
 a=rtpmap:103 ISAC/16000
 a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host generation 0 network-id 1 network-cost 10
a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host generation 0 network-id 2 network-cost 50
a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype active generation 0 network-id 1 network-cost 10
a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype active generation 0 network-id 2 network-cost 50
a=ice-ufrag:KQsy
a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
a=ice-options:trickle
a=fingerprint:sha-256 C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
a=rtcp-mux
a=rtcp-fb:111 transport-cc
a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
]
variable_ep_codec_string: [mod_spandsp.G722 at 8000h@20i at 64000b,CORE_PCM_MODULE.PCMU at 8000h@20i at 64000b,CORE_PCM_MODULE.PCMA at 8000h@20i at 64000b]
variable_endpoint_disposition: [DELAYED NEGOTIATION]
variable_DP_MATCH: [ARRAY::1001|:1001]
variable_call_uuid: []
variable_outside_call: [true]
variable_RFC2822_DATE: [Thu, 06 Oct 2022 10:18:15 +0000]
variable_export_vars: [RFC2822_DATE]
variable_current_application: [info]

 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 transfer(1001 XML default)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_ivr.c:2288 (sofia/external/1000 at 11.22.33.44) State Change CS_EXECUTE -> CS_ROUTING
 2022-10-06 10:18:15.078122 99.83% [NOTICE] switch_ivr.c:2295 Transfer sofia/external/1000 at 11.22.33.44 to XML[1001 at default]
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:647 (sofia/external/1000 at 11.22.33.44) State EXECUTE going to sleep
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_ROUTING (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1000 at 11.22.33.44) State ROUTING
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:149 Call appears to be already acknowledged
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:158 sofia/external/1000 at 11.22.33.44 SOFIA ROUTING
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:230 sofia/external/1000 at 11.22.33.44 Standard ROUTING
 2022-10-06 10:18:15.078122 99.83% [INFO] mod_dialplan_xml.c:639 Processing 1000 <1000>->1001 in context default
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->unloop] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->tod_example] continue=true
 Dialplan: sofia/external/1000 at 11.22.33.44 Date/Time Match (PASS) [tod_example] break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(open=true)
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->holiday_example] continue=true
 Dialplan: sofia/external/1000 at 11.22.33.44 Date/TimeMatch (FAIL) [holiday_example] break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->global-intercept] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->group-intercept] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->intercept-ext] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->redial] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->global] continue=true
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [global] ${call_debug}(true) =~ /^true$/ break=never
 Dialplan: sofia/external/1000 at 11.22.33.44 Action info()
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [global] ${default_password}() =~ /^1234$/ break=never
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [global] ${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=never
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [global] ${switch_r_sdp}(v=0
 o=- 8689874841498562319 2 IN IP4 127.0.0.1
 s=-
 t=0 0
 a=group:BUNDLE 0
 a=extmap-allow-mixed
 a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
 m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113 126
 c=IN IP4 192.168.1.64
 a=rtpmap:111 opus/48000/2
 a=fmtp:111 minptime=10;useinbandfec=1
 a=rtpmap:63 red/48000/2
 a=fmtp:63 111/111
 a=rtpmap:103 ISAC/16000
 a=rtpmap:104 ISAC/32000
 a=rtpmap:9 G722/8000
 a=rtpmap:0 PCMU/8000
 a=rtpmap:8 PCMA/8000
 a=rtpmap:106 CN/32000
 a=rtpmap:105 CN/16000
 a=rtpmap:13 CN/8000
 a=rtpmap:110 telephone-event/48000
 a=rtpmap:112 telephone-event/32000
 a=rtpmap:113 telephone-event/16000
 a=rtpmap:126 telephone-event/8000
 a=rtcp:9 IN IP4 0.0.0.0
 a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host generation 0 network-id 1 network-cost 10
 a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host generation 0 network-id 2 network-cost 50
 a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype active generation 0 network-id 1 network-cost 10
 a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype active generation 0 network-id 2 network-cost 50
 a=ice-ufrag:KQsy
 a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
 a=ice-options:trickle
 a=fingerprint:sha-256 C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
 a=setup:actpass
 a=mid:0
 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
 a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
 a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
 a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
 a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
 a=rtcp-mux
 a=rtcp-fb:111 transport-cc
 a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
 a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
 Dialplan: sofia/external/1000 at 11.22.33.44 Absolute Condition [global]
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-last_dial/global/${uuid})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->snom-demo-2] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->snom-demo-1] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->eavesdrop] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->eavesdrop] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->call_return] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->del-group] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->add-group] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->call-group-simo] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->call-group-order] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->extension-intercom] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 parsing [default->Local_Extension] continue=false
 Dialplan: sofia/external/1000 at 11.22.33.44 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false
 Dialplan: sofia/external/1000 at 11.22.33.44 Action export(dialed_extension=1001)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action bind_meta_app(1 b s execute_extension::dx XML features)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action bind_meta_app(3 b s execute_extension::cf XML features)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(ringback=${us-ring})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(transfer_ringback=local_stream://moh)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(call_timeout=10)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(hangup_after_bridge=true)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(continue_on_fail=true)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(ignore_sdp_ice=true)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(codec_string=G722,PCMU,PCMA)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action bridge(user/${dialed_extension}@${domain_name})
 Dialplan: sofia/external/1000 at 11.22.33.44 Action answer()
 Dialplan: sofia/external/1000 at 11.22.33.44 Action sleep(1000)
 Dialplan: sofia/external/1000 at 11.22.33.44 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:281 (sofia/external/1000 at 11.22.33.44) State Change CS_ROUTING -> CS_EXECUTE
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1000 at 11.22.33.44) State ROUTING going to sleep
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_EXECUTE (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:647 (sofia/external/1000 at 11.22.33.44) State EXECUTE
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:213 sofia/external/1000 at 11.22.33.44 SOFIA EXECUTE
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:323 sofia/external/1000 at 11.22.33.44 Standard EXECUTE
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(open=true)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [open]=[true]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 info()
 2022-10-06 10:18:15.078122 99.83% [INFO] mod_dptools.c:1886 CHANNEL_DATA:
 Channel-State: [CS_EXECUTE]
 Channel-Call-State: [RINGING]
 Channel-State-Number: [4]
 Channel-Name: [sofia/external/1000 at 11.22.33.44]
 Unique-ID: []
 Call-Direction: [inbound]
 Presence-Call-Direction: [inbound]
 Channel-HIT-Dialplan: [true]
 Channel-Call-UUID: []
 Answer-State: [ringing]
 Caller-Direction: [inbound]
 Caller-Logical-Direction: [inbound]
 Caller-Username: [1000]
 Caller-Dialplan: [XML]
 Caller-Caller-ID-Name: [1000]
 Caller-Caller-ID-Number: [1000]
 Caller-Orig-Caller-ID-Name: [1000]
 Caller-Orig-Caller-ID-Number: [1000]
 Caller-Network-Addr: [3.7.130.46]
 Caller-ANI: [1000]
 Caller-Destination-Number: [1001]
 Caller-Unique-ID: []
 Caller-Source: [mod_sofia]
 Caller-Transfer-Source: [1665051495:f05494e0-f314-429a-9501-8b58386b975e:bl_xfer:1001/default/XML]
 Caller-Context: [default]
 Caller-RDNIS: [1001]
 Caller-Channel-Name: [sofia/external/1000 at 11.22.33.44]
 Caller-Profile-Index: [2]
 Caller-Profile-Created-Time: [1665051495078122]
 Caller-Channel-Created-Time: [1665051495078122]
 Caller-Channel-Answered-Time: [0]
 Caller-Channel-Progress-Time: [0]
 Caller-Channel-Progress-Media-Time: [0]
 Caller-Channel-Hangup-Time: [0]
 Caller-Channel-Transfer-Time: [0]
 Caller-Channel-Resurrect-Time: [0]
 Caller-Channel-Bridged-Time: [0]
 Caller-Channel-Last-Hold: [0]
 Caller-Channel-Hold-Accum: [0]
 Caller-Screen-Bit: [true]
 Caller-Privacy-Hide-Name: [false]
 Caller-Privacy-Hide-Number: [false]
 variable_direction: [inbound]
 variable_uuid: []
 variable_session_id: [11]
 variable_sip_from_user: [1000]
 variable_sip_from_uri: [1000 at 11.22.33.44]
 variable_sip_from_host: [11.22.33.44]
 variable_video_media_flow: [disabled]
 variable_audio_media_flow: [disabled]
 variable_text_media_flow: [disabled]
 variable_channel_name: [sofia/external/1000 at 11.22.33.44]
 variable_sip_call_id: [aoc0tkcjs47mrj5n1jl4]
 variable_sip_local_network_addr: [11.22.33.44]
 variable_sip_network_ip: [3.7.130.46]
 variable_sip_network_port: [54985]
 variable_sip_invite_stamp: [1665051495078122]
 variable_sip_received_ip: [3.7.130.46]
 variable_sip_received_port: [54985]
 variable_sip_via_protocol: [wss]
 variable_sip_from_user_stripped: [1000]
 variable_sip_from_tag: [jimkkm04qn]
 variable_sofia_profile_name: [external]
 variable_sofia_profile_url: [sip:mod_sofia at 11.22.33.44:5080]
 variable_recovery_profile_name: [external]
 variable_sip_full_via: [SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985]
 variable_sip_full_from: [<sip:1000 at 11.22.33.44>;tag=jimkkm04qn]
 variable_sip_full_to: [<sip:1001 at 11.22.33.44>]
 variable_sip_allow: [INVITE, ACK, CANCEL, BYE, UPDATE, MESSAGE, OPTIONS, REFER, INFO, NOTIFY]
 variable_sip_req_user: [1001]
 variable_sip_req_uri: [1001 at 11.22.33.44]
 variable_sip_req_host: [11.22.33.44]
 variable_sip_to_user: [1001]
 variable_sip_to_uri: [1001 at 11.22.33.44]
 variable_sip_to_host: [11.22.33.44]
 variable_sip_contact_params: [ob]
 variable_sip_contact_user: [1000]
 variable_sip_contact_uri: [1000 at 11.22.33.44]
 variable_sip_contact_host: [11.22.33.44]
 variable_rtp_use_codec_string: [G722,PCMU,PCMA]
 variable_sip_user_agent: [JsSIP 3.9.1]
 variable_sip_via_host: [11.22.33.44]
 variable_sip_via_rport: [54985]
 variable_sip_h_X-Test: [tester-tested]
 variable_sip_nat_detected: [true]
 variable_switch_r_sdp: [v=0
 o=- 8689874841498562319 2 IN IP4 127.0.0.1
 s=-
 t=0 0
 a=group:BUNDLE 0
 a=extmap-allow-mixed
 a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
 m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113 126
 c=IN IP4 192.168.1.64
 a=rtpmap:111 opus/48000/2
 a=fmtp:111 minptime=10;useinbandfec=1
 a=rtpmap:63 red/48000/2
 a=fmtp:63 111/111
 a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host generation 0 network-id 1 network-cost 10
a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host generation 0 network-id 2 network-cost 50
a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype active generation 0 network-id 1 network-cost 10
a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype active generation 0 network-id 2 network-cost 50
a=ice-ufrag:KQsy
a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
a=ice-options:trickle
a=fingerprint:sha-256 C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
a=rtcp-mux
a=rtcp-fb:111 transport-cc
a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX 871ec968-71eb-4810-a9ff-dcd4c80705b2
]
variable_ep_codec_string: [mod_spandsp.G722 at 8000h@20i at 64000b,CORE_PCM_MODULE.PCMU at 8000h@20i at 64000b,CORE_PCM_MODULE.PCMA at 8000h@20i at 64000b]
variable_endpoint_disposition: [DELAYED NEGOTIATION]
variable_outside_call: [true]
variable_RFC2822_DATE: [Thu, 06 Oct 2022 10:18:15 +0000]
variable_export_vars: [RFC2822_DATE]
variable_max_forwards: [68]
variable_transfer_history: [1665051495:f05494e0-f314-429a-9501-8b58386b975e:bl_xfer:1001/default/XML] EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-spymap/1000/)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-last_dial/1000/1001)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-last_dial/global/)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 export(RFC2822_DATE=Thu, 06 Oct 2022 10:18:15 +0000)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 export(dialed_extension=1001)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [dialed_extension]=[1001]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 bind_meta_app(1 b s execute_extension::dx XML features)
 2022-10-06 10:18:15.078122 99.83% [INFO] switch_ivr_async.c:4780 Bound B-Leg: *1 execute_extension::dx XML features
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1000.2022-10-06-10-18-15.wav)
 2022-10-06 10:18:15.078122 99.83% [INFO] switch_ivr_async.c:4780 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1000.2022-10-06-10-18-15.wav
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 bind_meta_app(3 b s execute_extension::cf XML features)
 2022-10-06 10:18:15.078122 99.83% [INFO] switch_ivr_async.c:4780 Bound B-Leg: *3 execute_extension::cf XML features
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 bind_meta_app(4 b s execute_extension::att_xfer XML features)
 2022-10-06 10:18:15.078122 99.83% [INFO] switch_ivr_async.c:4780 Bound B-Leg: *4 execute_extension::att_xfer XML features
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(ringback=%(2000,4000,440,480))
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [ringback]=[%(2000,4000,440,480)]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(transfer_ringback=local_stream://moh)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [transfer_ringback]=[local_stream://moh]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(call_timeout=10)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [call_timeout]=[10]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(hangup_after_bridge=true)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [hangup_after_bridge]=[true]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(continue_on_fail=true)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [continue_on_fail]=[true]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(ignore_sdp_ice=true)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [ignore_sdp_ice]=[true]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(codec_string=G722,PCMU,PCMA)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [codec_string]=[G722,PCMU,PCMA]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-call_return/1001/1000)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-last_dial_ext/1001/)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 set(called_party_callgroup=techsupport)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_dptools.c:1673 SET sofia/external/1000 at 11.22.33.44 [called_party_callgroup]=[techsupport]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-last_dial_ext/techsupport/)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-last_dial_ext/global/)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 hash(insert/11.22.33.44-last_dial/techsupport/)
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 bridge(user/1001 at 11.22.33.44)
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000] to event
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000] to event
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [dialed_extension]=[1001] to event
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000] to event
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000] to event
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [dialed_extension]=[1001] to event
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [NOTICE] switch_channel.c:1123 New Channel sofia/external/1001 at 11.22.33.44 [d4ae71c1-0a98-4e97-a991-9f2bec4aba59]
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:5121 (sofia/external/1001 at 11.22.33.44) State Change CS_NEW -> CS_INIT
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001 at 11.22.33.44) Running State Change CS_INIT (Cur 2 Tot 12)
 2022-10-06 10:18:15.078122 99.83% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:624 (sofia/external/1001 at 11.22.33.44) State INIT
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:97 sofia/external/1001 at 11.22.33.44 SOFIA INIT
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia_glue.c:1623 sip:1001 at 3.7.130.46:54991 Setting proxy route to sofia/external/1001 at 11.22.33.44
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [INFO] sofia_glue.c:1654 sofia/external/1001 at 11.22.33.44 sending invite call-id: (null)
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia_glue.c:1657 sofia/external/1001 at 11.22.33.44 sending invite version: 1.10.8-dev git 98d2e62 2022-09-09 13:32:35Z 64bit
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 Local SDP:
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 v=0
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 o=FreeSWITCH 1665025989 1665025990 IN IP4 11.22.33.44
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 s=FreeSWITCH
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 c=IN IP4 11.22.33.44
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 t=0 0
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 m=audio 25506 RTP/AVP 9 0 8 101
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=rtpmap:9 G722/8000
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=rtpmap:0 PCMU/8000
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=rtpmap:8 PCMA/8000
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=rtpmap:101 telephone-event/8000
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=fmtp:101 0-15
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=ptime:20
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 a=sendrecv
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:40 sofia/external/1001 at 11.22.33.44 Standard INIT
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:48 (sofia/external/1001 at 11.22.33.44) State Change CS_INIT -> CS_ROUTING
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:624 (sofia/external/1001 at 11.22.33.44) State INIT going to sleep
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001 at 11.22.33.44) Running State Change CS_ROUTING (Cur 2 Tot 12)
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1001 at 11.22.33.44) State ROUTING
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] mod_sofia.c:158 sofia/external/1001 at 11.22.33.44 SOFIA ROUTING
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_ivr_originate.c:67 (sofia/external/1001 at 11.22.33.44) State Change CS_ROUTING -> CS_CONSUME_MEDIA
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1001 at 11.22.33.44) State ROUTING going to sleep
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001 at 11.22.33.44) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 12)
send 1179 bytes to udp/[3.7.130.46]:54991 at 10:18:15.089689:
------------------------------------------------------------------------
INVITE sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKjXBpZSprDKDta
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 67
From: "1000" <sip:1000 at 11.22.33.44>;tag=1UK4c7mvU8yjc
To: <sip:1001 at 11.22.33.44>
Call-ID: 07d93936-c003-123b-ee87-0abef6a004ad
CSeq: 57971955 INVITE
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uac
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 272
X-Test: tester-tested
X-FS-Support: update_display,send_info
Remote-Party-ID: "1000" <sip:1000 at 11.22.33.44>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1665025989 1665025990 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
m=audio 25506 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:659 (sofia/external/1001 at 11.22.33.44) State CONSUME_MEDIA
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:659 (sofia/external/1001 at 11.22.33.44) State CONSUME_MEDIA going to sleep
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7499 Channel sofia/external/1001 at 11.22.33.44 entering state [calling][0]
send 1179 bytes to udp/[3.7.130.46]:54991 at 10:18:16.090150:
------------------------------------------------------------------------
INVITE sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKjXBpZSprDKDta
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 67
From: "1000" <sip:1000 at 11.22.33.44>;tag=1UK4c7mvU8yjc
To: <sip:1001 at 11.22.33.44>
Call-ID: 07d93936-c003-123b-ee87-0abef6a004ad
CSeq: 57971955 INVITE
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uac
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 272
X-Test: tester-tested
X-FS-Support: update_display,send_info
Remote-Party-ID: "1000" <sip:1000 at 11.22.33.44>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1665025989 1665025990 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
m=audio 25506 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

send 828 bytes to udp/[3.7.130.46]:54807 at 10:18:17.689199:
------------------------------------------------------------------------
NOTIFY sip:1000 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKHmjXXy5mgaQ7e
Route: <sip:1000 at 3.7.130.46:54807>
Max-Forwards: 70
From: <sip:1000 at 11.22.33.44>;tag=XQe15tHe7457D
To: <sip:1000 at 11.22.33.44>
Call-ID: 02d75bac-c003-123b-ee87-0abef6a004ad
CSeq: 57971951 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1000 at 11.22.33.44

send 1179 bytes to udp/[3.7.130.46]:54991 at 10:18:18.091309:
------------------------------------------------------------------------
INVITE sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKjXBpZSprDKDta
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 67
From: "1000" <sip:1000 at 11.22.33.44>;tag=1UK4c7mvU8yjc
To: <sip:1001 at 11.22.33.44>
Call-ID: 07d93936-c003-123b-ee87-0abef6a004ad
CSeq: 57971955 INVITE
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uac
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 272
X-Test: tester-tested
X-FS-Support: update_display,send_info
Remote-Party-ID: "1000" <sip:1000 at 11.22.33.44>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1665025989 1665025990 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
m=audio 25506 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

send 828 bytes to udp/[3.7.130.46]:54991 at 10:18:18.188436:
------------------------------------------------------------------------
NOTIFY sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKgBS4U3mHK10mK
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 70
From: <sip:1001 at 11.22.33.44>;tag=tv2p09y3Fa3FB
To: <sip:1001 at 11.22.33.44>
Call-ID: fe5e6482-c002-123b-ee87-0abef6a004ad
CSeq: 57971947 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1001 at 11.22.33.44

recv 533 bytes from wss/[3.7.130.46]:54960 at 10:18:19.388260:
------------------------------------------------------------------------
REGISTER sip:11.22.33.44 SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK3577297
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>
From: <sip:1001 at 11.22.33.44>;tag=gjrrufs90u
Call-ID: e4o0m6ftcksfj4rj8nqg5h
CSeq: 14 REGISTER
Contact: <sip:1001 at 11.22.33.44>;+sip.ice;reg-id=1;+sip.instance="<urn:uuid:7c348d8e-0192-4b0a-b86c-ac0b1d2fb3e6>";expires=600
Expires: 600
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

2022-10-06 10:18:19.378126 99.80% [DEBUG] sofia_reg.c:1842 Send challenge for [1001 at 11.22.33.44]
send 612 bytes to wss/[3.7.130.46]:54960 at 10:18:19.388901:
------------------------------------------------------------------------
SIP/2.0 401 Unauthorized
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK3577297;received=3.7.130.46;rport=54960
From: <sip:1001 at 11.22.33.44>;tag=gjrrufs90u
To: <sip:1001 at 11.22.33.44>;tag=24cXe25ZrHN5Q
Call-ID: e4o0m6ftcksfj4rj8nqg5h
CSeq: 14 REGISTER
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
WWW-Authenticate: Digest realm="11.22.33.44", nonce="43cdbf91-3080-4b61-a0a3-7dff4f795914", algorithm=MD5, qop="auth"
Content-Length: 0

recv 774 bytes from wss/[3.7.130.46]:54960 at 10:18:19.828261:
------------------------------------------------------------------------
REGISTER sip:11.22.33.44 SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK8007679
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>
From: <sip:1001 at 11.22.33.44>;tag=gjrrufs90u
Call-ID: e4o0m6ftcksfj4rj8nqg5h
CSeq: 15 REGISTER
Authorization: Digest algorithm=MD5, username="1001", realm="11.22.33.44", nonce="43cdbf91-3080-4b61-a0a3-7dff4f795914", uri="sip:11.22.33.44", response="f0f94fafc81e2601b464fc31a1edb26e", qop=auth, cnonce="27hiicku8gov", nc=00000001
Contact: <sip:1001 at 11.22.33.44>;+sip.ice;reg-id=1;+sip.instance="<urn:uuid:7c348d8e-0192-4b0a-b86c-ac0b1d2fb3e6>";expires=600
Expires: 600
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'record_stereo' = 'true'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'default_gateway' = 'example.com'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'default_areacode' = '918'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'transfer_fallback_extension' = 'operator'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'toll_allow' = 'domestic,international,local'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'accountcode' = '1001'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'user_context' = 'default'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'effective_caller_id_name' = 'Extension 1001'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'effective_caller_id_number' = '1001'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'outbound_caller_id_name' = 'OutboundAgent_1'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:3477 event_add_header -> 'callgroup' = 'techsupport'
2022-10-06 10:18:19.818121 99.80% [DEBUG] sofia_reg.c:2089 Register:
From:    [1001 at 11.22.33.44]
Contact: ["" <sip:1001 at 11.22.33.44;fs_nat=yes;fs_path=sip%3A1001%403.7.130.46%3A54960>]
Expires: [600]
send 565 bytes to wss/[3.7.130.46]:54960 at 10:18:19.830018:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK8007679;received=3.7.130.46;rport=54960
From: <sip:1001 at 11.22.33.44>;tag=gjrrufs90u
To: <sip:1001 at 11.22.33.44>;tag=3D6NgXp3NtBrK
Call-ID: e4o0m6ftcksfj4rj8nqg5h
CSeq: 15 REGISTER
Contact: <sip:1001 at 11.22.33.44>;expires=600
Date: Thu, 06 Oct 2022 10:18:19 GMT
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0

send 828 bytes to udp/[3.7.130.46]:54807 at 10:18:21.689440:
------------------------------------------------------------------------
NOTIFY sip:1000 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKHmjXXy5mgaQ7e
Route: <sip:1000 at 3.7.130.46:54807>
Max-Forwards: 70
From: <sip:1000 at 11.22.33.44>;tag=XQe15tHe7457D
To: <sip:1000 at 11.22.33.44>
Call-ID: 02d75bac-c003-123b-ee87-0abef6a004ad
CSeq: 57971951 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1000 at 11.22.33.44

send 1179 bytes to udp/[3.7.130.46]:54991 at 10:18:22.092573:
------------------------------------------------------------------------
INVITE sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKjXBpZSprDKDta
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 67
From: "1000" <sip:1000 at 11.22.33.44>;tag=1UK4c7mvU8yjc
To: <sip:1001 at 11.22.33.44>
Call-ID: 07d93936-c003-123b-ee87-0abef6a004ad
CSeq: 57971955 INVITE
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uac
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 272
X-Test: tester-tested
X-FS-Support: update_display,send_info
Remote-Party-ID: "1000" <sip:1000 at 11.22.33.44>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1665025989 1665025990 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
m=audio 25506 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

send 828 bytes to udp/[3.7.130.46]:54991 at 10:18:22.188699:
------------------------------------------------------------------------
NOTIFY sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKgBS4U3mHK10mK
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 70
From: <sip:1001 at 11.22.33.44>;tag=tv2p09y3Fa3FB
To: <sip:1001 at 11.22.33.44>
Call-ID: fe5e6482-c002-123b-ee87-0abef6a004ad
CSeq: 57971947 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1001 at 11.22.33.44

d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [NOTICE] switch_ivr_originate.c:3799 Hangup sofia/external/1001 at 11.22.33.44 [CS_CONSUME_MEDIA] [NO_ANSWER]
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001 at 11.22.33.44) Running State Change CS_HANGUP (Cur 2 Tot 12)
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:844 (sofia/external/1001 at 11.22.33.44) Callstate Change DOWN -> HANGUP
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:846 (sofia/external/1001 at 11.22.33.44) State HANGUP
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] mod_sofia.c:468 Channel sofia/external/1001 at 11.22.33.44 hanging up, cause: NO_ANSWER
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] mod_sofia.c:536 Sending CANCEL to sofia/external/1001 at 11.22.33.44
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:59 sofia/external/1001 at 11.22.33.44 Standard HANGUP, cause: NO_ANSWER
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:846 (sofia/external/1001 at 11.22.33.44) State HANGUP going to sleep
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:616 (sofia/external/1001 at 11.22.33.44) State Change CS_HANGUP -> CS_REPORTING
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001 at 11.22.33.44) Running State Change CS_REPORTING (Cur 2 Tot 12)
 2022-10-06 10:18:25.018122 99.80% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [user] cause: [NO_ANSWER]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 19 [NO_ANSWER]
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:932 (sofia/external/1001 at 11.22.33.44) State REPORTING
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:168 sofia/external/1001 at 11.22.33.44 Standard REPORTING, cause: NO_ANSWER
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:932 (sofia/external/1001 at 11.22.33.44) State REPORTING going to sleep
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:607 (sofia/external/1001 at 11.22.33.44) State Change CS_REPORTING -> CS_DESTROY
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_session.c:1747 Session 12 (sofia/external/1001 at 11.22.33.44) Locked, Waiting on external entities
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [NOTICE] switch_core_session.c:1765 Session 12 (sofia/external/1001 at 11.22.33.44) Ended
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [NOTICE] switch_core_session.c:1769 Close Channel sofia/external/1001 at 11.22.33.44 [CS_DESTROY]
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:735 (sofia/external/1001 at 11.22.33.44) Running State Change CS_DESTROY (Cur 1 Tot 12)
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:745 (sofia/external/1001 at 11.22.33.44) State DESTROY
 2022-10-06 10:18:25.018122 99.80% [INFO] mod_dptools.c:3637 Originate Failed.  Cause: NO_ANSWER
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] mod_sofia.c:379 sofia/external/1001 at 11.22.33.44 SOFIA DESTROY
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:175 sofia/external/1001 at 11.22.33.44 Standard DESTROY
d4ae71c1-0a98-4e97-a991-9f2bec4aba59 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_state_machine.c:745 (sofia/external/1001 at 11.22.33.44) State DESTROY going to sleep
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 answer()
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [red:63:48000:20:0:2]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [red:63:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [red:63:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5579 Set telephone-event payload to 110 at 48000
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:3883 Set Codec sofia/external/1000 at 11.22.33.44 G722/8000 20 ms 160 samples 64000 bits 1 channels
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_codec.c:111 sofia/external/1000 at 11.22.33.44 Original read codec set to G722:9
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5928 Set telephone-event payload to 126 at 8000
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5986 sofia/external/1000 at 11.22.33.44 Set 2833 dtmf send payload to 126 recv payload to 126
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:8787 AUDIO RTP [sofia/external/1000 at 11.22.33.44] 10.10.6.12 port 29876 -> 192.168.1.64 port 59566 codec: 9 ms: 20
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:9007 Activating RTCP PORT 0
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_rtp.c:5017 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 59567
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 192.168.1.64:59567 2
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:9099 sofia/external/1000 at 11.22.33.44 Set 2833 dtmf send payload to 126
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:9106 sofia/external/1000 at 11.22.33.44 Set 2833 dtmf receive payload to 126
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:9129 sofia/external/1000 at 11.22.33.44 Set rtp dtmf delay to 40
 2022-10-06 10:18:25.018122 99.80% [NOTICE] sofia_media.c:90 Pre-Answer sofia/external/1000 at 11.22.33.44!
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_channel.c:3622 (sofia/external/1000 at 11.22.33.44) Callstate Change RINGING -> EARLY
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:8769 Audio params are unchanged for sofia/external/1000 at 11.22.33.44.
 2022-10-06 10:18:25.018122 99.80% [DEBUG] mod_sofia.c:913 Local SDP sofia/external/1000 at 11.22.33.44:
 v=0
 o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
 s=FreeSWITCH
 c=IN IP4 11.22.33.44
 t=0 0
 a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
 m=audio 29876 UDP/AVPF 9 126
 a=rtpmap:9 G722/8000
 a=rtpmap:126 telephone-event/8000
 a=ptime:20
 a=sendrecv
 a=rtcp:29877 IN IP4 11.22.33.44
 a=ice-ufrag:0OsMZPPHcIga8KUi
 a=ice-pwd:XaZYj9vC6oyD4TjUxCxnhcUk
 a=candidate:0153546995 1 udp 2130706431 11.22.33.44 29876 typ host generation 0
 a=candidate:0153546995 2 udp 2130706430 11.22.33.44 29877 typ host generation 0
 a=end-of-candidates
 a=ssrc:3007569695 cname:kmpRbjjGt625HQuP
 a=ssrc:3007569695 msid:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET a0
 a=ssrc:3007569695 mslabel:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
 a=ssrc:3007569695 label:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zETa0

 2022-10-06 10:18:25.018122 99.80% [NOTICE] mod_dptools.c:1408 Channel [sofia/external/1000 at 11.22.33.44] has been answered
send 985 bytes to wss/[3.7.130.46]:54985 at 10:18:25.032155:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
Contact: <sip:1001 at 11.22.33.44:5080;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 196
Remote-Party-ID: "1001" <sip:1001 at 11.22.33.44>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
m=audio 0 UDP/TLS/RTP/SAVPF 19

 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_channel.c:3950 (sofia/external/1000 at 11.22.33.44) Callstate Change EARLY -> ACTIVE
 2022-10-06 10:18:25.018122 99.80% [DEBUG] sofia.c:7499 Channel sofia/external/1000 at 11.22.33.44 entering state [completed][200]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 sleep(1000)
send 985 bytes to wss/[3.7.130.46]:54985 at 10:18:25.532271:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
Contact: <sip:1001 at 11.22.33.44:5080;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 196
Remote-Party-ID: "1001" <sip:1001 at 11.22.33.44>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
m=audio 0 UDP/TLS/RTP/SAVPF 19

send 828 bytes to udp/[3.7.130.46]:54807 at 10:18:25.690429:
------------------------------------------------------------------------
NOTIFY sip:1000 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKHmjXXy5mgaQ7e
Route: <sip:1000 at 3.7.130.46:54807>
Max-Forwards: 70
From: <sip:1000 at 11.22.33.44>;tag=XQe15tHe7457D
To: <sip:1000 at 11.22.33.44>
Call-ID: 02d75bac-c003-123b-ee87-0abef6a004ad
CSeq: 57971951 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1000 at 11.22.33.44

recv 411 bytes from wss/[3.7.130.46]:54985 at 10:18:25.873104:
------------------------------------------------------------------------
ACK sip:1001 at 11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK4909788
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

 2022-10-06 10:18:25.878122 99.80% [DEBUG] sofia.c:7499 Channel sofia/external/1000 at 11.22.33.44 entering state [ready][200]
 EXECUTE [depth=0] sofia/external/1000 at 11.22.33.44 bridge(loopback/app=voicemail:default 11.22.33.44 1001)
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:1954 (sofia/external/1000 at 11.22.33.44) Callstate Change ACTIVE -> RING_WAIT
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000] to event
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 06 Oct 2022 10:18:15 +0000] to event
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:1269 sofia/external/1000 at 11.22.33.44 EXPORTING[export_vars] [dialed_extension]=[1001] to event
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [NOTICE] switch_channel.c:1123 New Channel loopback/app=voicemail:default 11.22.33.44 1001-a [3277e15a-3b7d-4ddd-b49c-0194bb12ae4c]
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:166 loopback/app=voicemail:default 11.22.33.44 1001-a setup codec G722/8000/20
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:1191 setting loopback_from_uuid to 
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [NOTICE] switch_channel.c:1121 Rename Channel loopback/app=voicemail:default 11.22.33.44 1001-a->loopback/voicemail-a [3277e15a-3b7d-4ddd-b49c-0194bb12ae4c]
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:1262 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-a) Running State Change CS_INIT (Cur 2 Tot 13)
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:624 (loopback/voicemail-a) State INIT
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [NOTICE] switch_channel.c:1123 New Channel loopback/voicemail-b [aa8916bb-7820-4186-8d46-5c57ba1c1c00]
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:166 loopback/voicemail-b setup codec G722/8000/20
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:288 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:356 setting other_loopback_from_uuid on b leg to 
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:380 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:624 (loopback/voicemail-a) State INIT going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-b) Running State Change CS_INIT (Cur 3 Tot 14)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:624 (loopback/voicemail-b) State INIT
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:380 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:624 (loopback/voicemail-b) State INIT going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-b) Running State Change CS_ROUTING (Cur 3 Tot 14)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:2380 (loopback/voicemail-b) Callstate Change DOWN -> RINGING
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-a) Running State Change CS_ROUTING (Cur 3 Tot 14)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:640 (loopback/voicemail-b) State ROUTING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:412 loopback/voicemail-b CHANNEL ROUTING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:431 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:640 (loopback/voicemail-b) State ROUTING going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-b) Running State Change CS_EXECUTE (Cur 3 Tot 14)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:647 (loopback/voicemail-b) State EXECUTE
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:454 loopback/voicemail-b CHANNEL EXECUTE
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:640 (loopback/voicemail-a) State ROUTING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:323 loopback/voicemail-b Standard EXECUTE
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:412 loopback/voicemail-a CHANNEL ROUTING
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:640 (loopback/voicemail-a) State ROUTING going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 EXECUTE [depth=0] loopback/voicemail-b pre_answer()
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 14)
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:659 (loopback/voicemail-a) State CONSUME_MEDIA
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:681 CHANNEL CONSUME_MEDIA
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:659 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [NOTICE] mod_loopback.c:1026 Pre-Answer loopback/voicemail-a!
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_ivr_originate.c:3892 Originate Resulted in Success: [loopback/voicemail-a] Peer UUID: 3277e15a-3b7d-4ddd-b49c-0194bb12ae4c
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:3622 (loopback/voicemail-a) Callstate Change DOWN -> EARLY
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [NOTICE] mod_dptools.c:1478 Pre-Answer loopback/voicemail-b!
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:3622 (loopback/voicemail-b) Callstate Change RINGING -> EARLY
 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_channel.c:2178 (sofia/external/1000 at 11.22.33.44) Callstate Change RING_WAIT -> ACTIVE
aa8916bb-7820-4186-8d46-5c57ba1c1c00 EXECUTE [depth=0] loopback/voicemail-b voicemail(default 11.22.33.44 1001)
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_ivr_bridge.c:1791 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 14)
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-a) State EXCHANGE_MEDIA
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.018122 99.77% [DEBUG] mod_loopback.c:643 CHANNEL LOOPBACK
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.118122 99.77% [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.118122 99.77% [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.118122 99.77% [DEBUG] switch_ivr_play_say.c:262 Setting playback volume to 0
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.118122 99.77% [DEBUG] switch_ivr_play_say.c:1566 Codec Activated L16 at 16000hz 1 channels 20ms
send 828 bytes to udp/[3.7.130.46]:54991 at 10:18:26.189577:
------------------------------------------------------------------------
NOTIFY sip:1001 at 11.22.33.44 SIP/2.0
Via: SIP/2.0/UDP 11.22.33.44:5080;rport;branch=z9hG4bKgBS4U3mHK10mK
Route: <sip:1001 at 3.7.130.46:54991>
Max-Forwards: 70
From: <sip:1001 at 11.22.33.44>;tag=tv2p09y3Fa3FB
To: <sip:1001 at 11.22.33.44>
Call-ID: fe5e6482-c002-123b-ee87-0abef6a004ad
CSeq: 57971947 NOTIFY
Contact: <sip:mod_sofia at 11.22.33.44:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 66

Messages-Waiting: no
Message-Account: sip:1001 at 11.22.33.44

recv 411 bytes from wss/[3.7.130.46]:54985 at 10:18:26.335274:
------------------------------------------------------------------------
ACK sip:1001 at 11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK8228266
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

recv 462 bytes from wss/[3.7.130.46]:54985 at 10:18:26.584127:
------------------------------------------------------------------------
BYE sip:1001 at 11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK162798
Max-Forwards: 69
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3753 BYE
Reason: SIP ;cause=488; text="Not Acceptable Here"
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

 2022-10-06 10:18:26.578119 99.77% [NOTICE] sofia.c:1065 Hangup sofia/external/1000 at 11.22.33.44 [CS_EXECUTE] [NORMAL_CLEARING]
send 474 bytes to wss/[3.7.130.46]:54985 at 10:18:26.589414:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK162798;received=3.7.130.46;rport=54985
From: <sip:1000 at 11.22.33.44>;tag=jimkkm04qn
To: <sip:1001 at 11.22.33.44>;tag=0jtBBc4ryZ8Zg
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3753 BYE
User-Agent: FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0

3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_ivr_bridge.c:819 sofia/external/1000 at 11.22.33.44 ending bridge by request from write function
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/external/1000 at 11.22.33.44]
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [loopback/voicemail-a]
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_ivr_bridge.c:1023 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] mod_loopback.c:610 loopback/voicemail-a CHANNEL KILL
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-a) Running State Change CS_HANGUP (Cur 3 Tot 14)
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:844 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:846 (loopback/voicemail-a) State HANGUP
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] mod_loopback.c:569 loopback/voicemail-a CHANNEL HANGUP
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [NOTICE] mod_loopback.c:585 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL]
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] mod_loopback.c:610 loopback/voicemail-b CHANNEL KILL
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:59 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:846 (loopback/voicemail-a) State HANGUP going to sleep
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:616 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-a) Running State Change CS_REPORTING (Cur 3 Tot 14)
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:932 (loopback/voicemail-a) State REPORTING
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:168 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:932 (loopback/voicemail-a) State REPORTING going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_ivr_play_say.c:2015 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:607 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_session.c:1747 Session 13 (loopback/voicemail-a) Locked, Waiting on external entities
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_ivr_bridge.c:1893 sofia/external/1000 at 11.22.33.44 skip receive message [UNBRIDGE] (channel is hungup already)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_session.c:2977 sofia/external/1000 at 11.22.33.44 skip receive message [PHONE_EVENT] (channel is hungup already)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:647 (sofia/external/1000 at 11.22.33.44) State EXECUTE going to sleep
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_HANGUP (Cur 3 Tot 14)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:844 (sofia/external/1000 at 11.22.33.44) Callstate Change ACTIVE -> HANGUP
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_session.c:2977 loopback/voicemail-b skip receive message [PHONE_EVENT] (channel is hungup already)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:647 (loopback/voicemail-b) State EXECUTE going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-b) Running State Change CS_HANGUP (Cur 3 Tot 14)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:846 (sofia/external/1000 at 11.22.33.44) State HANGUP
 2022-10-06 10:18:26.578119 99.77% [DEBUG] mod_sofia.c:468 Channel sofia/external/1000 at 11.22.33.44 hanging up, cause: NORMAL_CLEARING
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:59 sofia/external/1000 at 11.22.33.44 Standard HANGUP, cause: NORMAL_CLEARING
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:846 (sofia/external/1000 at 11.22.33.44) State HANGUP going to sleep
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:616 (sofia/external/1000 at 11.22.33.44) State Change CS_HANGUP -> CS_REPORTING
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000 at 11.22.33.44) Running State Change CS_REPORTING (Cur 3 Tot 14)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:844 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:932 (sofia/external/1000 at 11.22.33.44) State REPORTING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:846 (loopback/voicemail-b) State HANGUP
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] mod_loopback.c:569 loopback/voicemail-b CHANNEL HANGUP
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:59 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_core_session.c:1765 Session 13 (loopback/voicemail-a) Ended
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:846 (loopback/voicemail-b) State HANGUP going to sleep
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_core_session.c:1769 Close Channel loopback/voicemail-a [CS_DESTROY]
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:616 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:168 sofia/external/1000 at 11.22.33.44 Standard REPORTING, cause: NORMAL_CLEARING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:581 (loopback/voicemail-b) Running State Change CS_REPORTING (Cur 2 Tot 14)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:932 (sofia/external/1000 at 11.22.33.44) State REPORTING going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:932 (loopback/voicemail-b) State REPORTING
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:168 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:932 (loopback/voicemail-b) State REPORTING going to sleep
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:735 (loopback/voicemail-a) Running State Change CS_DESTROY (Cur 2 Tot 14)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:607 (sofia/external/1000 at 11.22.33.44) State Change CS_REPORTING -> CS_DESTROY
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_session.c:1747 Session 11 (sofia/external/1000 at 11.22.33.44) Locked, Waiting on external entities
 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_core_session.c:1765 Session 11 (sofia/external/1000 at 11.22.33.44) Ended
 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_core_session.c:1769 Close Channel sofia/external/1000 at 11.22.33.44 [CS_DESTROY]
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:607 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_session.c:1747 Session 14 (loopback/voicemail-b) Locked, Waiting on external entities
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_core_session.c:1765 Session 14 (loopback/voicemail-b) Ended
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [NOTICE] switch_core_session.c:1769 Close Channel loopback/voicemail-b [CS_DESTROY]
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:745 (loopback/voicemail-a) State DESTROY
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:175 loopback/voicemail-a Standard DESTROY
3277e15a-3b7d-4ddd-b49c-0194bb12ae4c 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:745 (loopback/voicemail-a) State DESTROY going to sleep
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:735 (sofia/external/1000 at 11.22.33.44) Running State Change CS_DESTROY (Cur 0 Tot 14)
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:745 (sofia/external/1000 at 11.22.33.44) State DESTROY
 2022-10-06 10:18:26.578119 99.77% [DEBUG] mod_sofia.c:379 sofia/external/1000 at 11.22.33.44 SOFIA DESTROY
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:175 sofia/external/1000 at 11.22.33.44 Standard DESTROY
 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:745 (sofia/external/1000 at 11.22.33.44) State DESTROY going to sleep
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:735 (loopback/voicemail-b) Running State Change CS_DESTROY (Cur 0 Tot 14)
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:745 (loopback/voicemail-b) State DESTROY
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:175 loopback/voicemail-b Standard DESTROY
aa8916bb-7820-4186-8d46-5c57ba1c1c00 2022-10-06 10:18:26.578119 99.77% [DEBUG] switch_core_state_machine.c:745 (loopback/voicemail-b) State DESTROY going to sleep