[Freeswitch-users] sofia - wrong (external) IP address in contact for local calls
Dušan Dragić
dragic.dusan at gmail.com
Mon Jun 10 22:47:59 UTC 2019
Hi,
So, after not using freeswitch for a few years, I just did a clean
install of Freeswitch 1.8.6 on debian 9 using packages from the repo
and have a small issue maybe someone can help me with.
I'm using the vanilla config here to keep it simple, also Freeswitch
is started with -nonat.
The problem I encountered is the contact field for local calls (on the
same IP subnet as freeswitch) on the internal profile contains the
external IP address which makes the phone send the response to the
wrong IP. You can find attached a complete debug log with sip trace of
a call between ext 1007 (192.168.0.66) and ext 1008 (192.168.0.65).
Freeswitch is 192.168.0.140.
The profile contains the default params:
<param name="rtp-ip" value="$${local_ip_v4}"/>
<param name="sip-ip" value="$${local_ip_v4}"/>
<param name="ext-rtp-ip" value="$${external_rtp_ip}"/>
<param name="ext-sip-ip" value="$${external_rtp_ip}"/>
This is what I get from sofia status:
freeswitch at deb9> sofia status profile internal
=================================================================================================
Name internal
Domain Name N/A
Auto-NAT false
DBName sofia_reg_internal
Pres Hosts 192.168.0.140,192.168.0.140
Dialplan XML
Context public
Challenge Realm auto_from
RTP-IP 192.168.0.140
Ext-RTP-IP 93.86.XX.XX
SIP-IP 192.168.0.140
Ext-SIP-IP 93.86.XX.XX
URL sip:mod_sofia at 93.86.XX.XX:5060
BIND-URL
sip:mod_sofia at 93.86.XX.XX:5060;maddr=192.168.0.140;transport=udp,tcp
WS-BIND-URL sip:mod_sofia at 192.168.0.140:5066;transport=ws
WSS-BIND-URL sips:mod_sofia at 192.168.0.140:7443;transport=wss
HOLD-MUSIC local_stream://moh
OUTBOUND-PROXY N/A
CODECS IN OPUS,G722,PCMU,PCMA,H264,VP8
CODECS OUT OPUS,G722,PCMU,PCMA,H264,VP8
TEL-EVENT 101
DTMF-MODE rfc2833
CNG 13
SESSION-TO 0
MAX-DIALOG 0
NOMEDIA false
LATE-NEG true
PROXY-MEDIA false
ZRTP-PASSTHRU true
AGGRESSIVENAT false
CALLS-IN 0
FAILED-CALLS-IN 0
CALLS-OUT 0
FAILED-CALLS-OUT 0
REGISTRATIONS 2
Is this the correct behavior? If I remove ext-rtp-ip and ext-sip-ip
params from the config it works, but am I missing something obvious or
is this a bug?
--
Dušan Dragić
-------------- next part --------------
recv 1572 bytes from udp/[192.168.0.66]:2048 at 23:32:04.627618:
------------------------------------------------------------------------
INVITE sip:1008 at 192.168.0.140;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-vdzthrr3f49z;rport
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 1 INVITE
Max-Forwards: 70
Contact: <sip:1007 at 192.168.0.66:2048;line=qws41d8u>;reg-id=1
X-Serialnumber: 00041335F375
P-Key-Flags: keys="3"
User-Agent: snom320/8.4.35
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Call-Info: <sip:192.168.0.140>;appearance-index=1
Session-Expires: 3600;refresher=uas
Min-SE: 90
Content-Type: application/sdp
Content-Length: 772
v=0
o=root 512248378 512248378 IN IP4 192.168.0.66
s=call
c=IN IP4 192.168.0.66
t=0 0
m=audio 60750 RTP/SAVP 0 8 9 99 3 18 4 101
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=audio 60750 RTP/AVP 0 8 9 99 3 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
2019-06-10 23:32:04.166338 [NOTICE] switch_channel.c:1114 New Channel sofia/internal/1007 at 192.168.0.140 [64a69c8e-3378-4e59-a4b5-a69d26fcf342]
2019-06-10 23:32:04.166338 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_NEW (Cur 1 Tot 8)
2019-06-10 23:32:04.166338 [DEBUG] sofia.c:10164 sofia/internal/1007 at 192.168.0.140 receiving invite from 192.168.0.66:2048 version: 1.8.6 -7-93b4c92e75 64bit
2019-06-10 23:32:04.166338 [DEBUG] sofia.c:10260 verifying acl "domains" for ip/port 192.168.0.66:0.
send 828 bytes to udp/[192.168.0.66]:2048 at 23:32:04.629650:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-vdzthrr3f49z;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=mt65DH0Qev5ea
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 1 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="192.168.0.140", nonce="2a738596-31a3-47e6-9f8a-bc3b0ac10370", algorithm=MD5, qop="auth"
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:04.166338 [DEBUG] sofia.c:2413 detaching session 64a69c8e-3378-4e59-a4b5-a69d26fcf342
2019-06-10 23:32:04.166338 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1007 at 192.168.0.140) State NEW
recv 382 bytes from udp/[192.168.0.66]:2048 at 23:32:04.781223:
------------------------------------------------------------------------
ACK sip:1008 at 192.168.0.140;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-vdzthrr3f49z;rport
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=mt65DH0Qev5ea
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 1 ACK
Max-Forwards: 70
Contact: <sip:1007 at 192.168.0.66:2048;line=qws41d8u>;reg-id=1
Content-Length: 0
------------------------------------------------------------------------
recv 1821 bytes from udp/[192.168.0.66]:2048 at 23:32:04.796942:
------------------------------------------------------------------------
INVITE sip:1008 at 192.168.0.140;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Max-Forwards: 70
Contact: <sip:1007 at 192.168.0.66:2048;line=qws41d8u>;reg-id=1
X-Serialnumber: 00041335F375
P-Key-Flags: keys="3"
User-Agent: snom320/8.4.35
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Call-Info: <sip:192.168.0.140>;appearance-index=1
Session-Expires: 3600;refresher=uas
Min-SE: 90
Proxy-Authorization: Digest username="1007",realm="192.168.0.140",nonce="2a738596-31a3-47e6-9f8a-bc3b0ac10370",uri="sip:1008 at 192.168.0.140;user=phone",qop=auth,nc=00000001,cnonce="4bc00e11",response="9e66e2b772db6bac1abe8c47bdb7650d",algorithm=MD5
Content-Type: application/sdp
Content-Length: 772
v=0
o=root 512248378 512248378 IN IP4 192.168.0.66
s=call
c=IN IP4 192.168.0.66
t=0 0
m=audio 60750 RTP/SAVP 0 8 9 99 3 18 4 101
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=audio 60750 RTP/AVP 0 8 9 99 3 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
2019-06-10 23:32:04.346344 [DEBUG] sofia.c:2522 Re-attaching to session 64a69c8e-3378-4e59-a4b5-a69d26fcf342
2019-06-10 23:32:04.346344 [DEBUG] sofia.c:10164 sofia/internal/1007 at 192.168.0.140 receiving invite from 192.168.0.66:2048 version: 1.8.6 -7-93b4c92e75 64bit
2019-06-10 23:32:04.346344 [DEBUG] sofia.c:10260 verifying acl "domains" for ip/port 192.168.0.66:0.
2019-06-10 23:32:04.346344 [DEBUG] sofia.c:7323 Channel sofia/internal/1007 at 192.168.0.140 entering state [received][100]
2019-06-10 23:32:04.346344 [DEBUG] sofia.c:7333 Remote SDP:
v=0
o=root 512248378 512248378 IN IP4 192.168.0.66
s=call
c=IN IP4 192.168.0.66
t=0 0
m=audio 60750 RTP/SAVP 0 8 9 99 3 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd
a=ptime:20
m=audio 60750 RTP/AVP 0 8 9 99 3 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2019-06-10 23:32:04.346344 [DEBUG] sofia.c:7727 (sofia/internal/1007 at 192.168.0.140) State Change CS_NEW -> CS_INIT
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_INIT (Cur 1 Tot 8)
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1007 at 192.168.0.140) State INIT
2019-06-10 23:32:04.346344 [DEBUG] mod_sofia.c:93 sofia/internal/1007 at 192.168.0.140 SOFIA INIT
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1007 at 192.168.0.140 Standard INIT
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1007 at 192.168.0.140) State Change CS_INIT -> CS_ROUTING
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1007 at 192.168.0.140) State INIT going to sleep
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_ROUTING (Cur 1 Tot 8)
2019-06-10 23:32:04.346344 [DEBUG] switch_channel.c:2293 (sofia/internal/1007 at 192.168.0.140) Callstate Change DOWN -> RINGING
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1007 at 192.168.0.140) State ROUTING
send 324 bytes to udp/[192.168.0.66]:2048 at 23:32:04.813277:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:04.346344 [DEBUG] mod_sofia.c:154 sofia/internal/1007 at 192.168.0.140 SOFIA ROUTING
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1007 at 192.168.0.140 Standard ROUTING
2019-06-10 23:32:04.346344 [INFO] mod_dialplan_xml.c:637 Processing Test 7 <1007>->1008 in context default
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1007 at 192.168.0.140 Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1007 at 192.168.0.140 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [global-intercept] destination_number(1008) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [group-intercept] destination_number(1008) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [intercept-ext] destination_number(1008) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->redial] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [redial] destination_number(1008) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->global] continue=true
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [global] ${default_password}(55.33.11) =~ /^1234$/ break=never
Dialplan: sofia/internal/1007 at 192.168.0.140 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/internal/1007 at 192.168.0.140 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (PASS) [global] ${switch_r_sdp}(v=0
o=root 512248378 512248378 IN IP4 192.168.0.66
s=call
c=IN IP4 192.168.0.66
t=0 0
m=audio 60750 RTP/SAVP 0 8 9 99 3 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd
a=ptime:20
m=audio 60750 RTP/AVP 0 8 9 99 3 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:99 G726-32/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(rtp_secure_media=true)
Dialplan: sofia/internal/1007 at 192.168.0.140 Absolute Condition [global]
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [snom-demo-2] destination_number(1008) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [snom-demo-1] destination_number(1008) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [eavesdrop] destination_number(1008) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [eavesdrop] destination_number(1008) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [call_return] destination_number(1008) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [del-group] destination_number(1008) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [add-group] destination_number(1008) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [call-group-simo] destination_number(1008) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [call-group-order] destination_number(1008) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (FAIL) [extension-intercom] destination_number(1008) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1007 at 192.168.0.140 Regex (PASS) [Local_Extension] destination_number(1008) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1007 at 192.168.0.140 Action export(dialed_extension=1008)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(call_timeout=30)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(continue_on_fail=true)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1007 at 192.168.0.140 Action answer()
Dialplan: sofia/internal/1007 at 192.168.0.140 Action sleep(1000)
Dialplan: sofia/internal/1007 at 192.168.0.140 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1007 at 192.168.0.140) State Change CS_ROUTING -> CS_EXECUTE
2019-06-10 23:32:04.346344 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1007 at 192.168.0.140) State ROUTING going to sleep
2019-06-10 23:32:04.366328 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_EXECUTE (Cur 1 Tot 8)
2019-06-10 23:32:04.366328 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1007 at 192.168.0.140) State EXECUTE
2019-06-10 23:32:04.366328 [DEBUG] mod_sofia.c:209 sofia/internal/1007 at 192.168.0.140 SOFIA EXECUTE
2019-06-10 23:32:04.366328 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1007 at 192.168.0.140 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(rtp_secure_media=true)
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [rtp_secure_media]=[true]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-spymap/1007/64a69c8e-3378-4e59-a4b5-a69d26fcf342)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-last_dial/1007/1008)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-last_dial/global/64a69c8e-3378-4e59-a4b5-a69d26fcf342)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 export(RFC2822_DATE=Mon, 10 Jun 2019 23:32:04 +0200)
2019-06-10 23:32:04.366328 [DEBUG] switch_channel.c:1306 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 10 Jun 2019 23:32:04 +0200]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 export(dialed_extension=1008)
2019-06-10 23:32:04.366328 [DEBUG] switch_channel.c:1306 EXPORT (export_vars) [dialed_extension]=[1008]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 bind_meta_app(1 b s execute_extension::dx XML features)
2019-06-10 23:32:04.366328 [INFO] switch_ivr_async.c:4414 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/1007.2019-06-10-23-32-04.wav)
2019-06-10 23:32:04.366328 [INFO] switch_ivr_async.c:4414 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/1007.2019-06-10-23-32-04.wav
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 bind_meta_app(3 b s execute_extension::cf XML features)
2019-06-10 23:32:04.366328 [INFO] switch_ivr_async.c:4414 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2019-06-10 23:32:04.366328 [INFO] switch_ivr_async.c:4414 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(ringback=%(2000,4000,440,480))
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [ringback]=[%(2000,4000,440,480)]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(transfer_ringback=local_stream://moh)
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [transfer_ringback]=[local_stream://moh]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(call_timeout=30)
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [call_timeout]=[30]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(hangup_after_bridge=true)
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(continue_on_fail=true)
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-call_return/1008/1007)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-last_dial_ext/1008/64a69c8e-3378-4e59-a4b5-a69d26fcf342)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 set(called_party_callgroup=techsupport)
2019-06-10 23:32:04.366328 [DEBUG] mod_dptools.c:1615 SET sofia/internal/1007 at 192.168.0.140 [called_party_callgroup]=[techsupport]
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-last_dial_ext/techsupport/64a69c8e-3378-4e59-a4b5-a69d26fcf342)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-last_dial_ext/global/64a69c8e-3378-4e59-a4b5-a69d26fcf342)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 hash(insert/192.168.0.140-last_dial/techsupport/64a69c8e-3378-4e59-a4b5-a69d26fcf342)
EXECUTE [depth=0] sofia/internal/1007 at 192.168.0.140 bridge(user/1008 at 192.168.0.140)
2019-06-10 23:32:04.366328 [DEBUG] switch_channel.c:1260 sofia/internal/1007 at 192.168.0.140 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 10 Jun 2019 23:32:04 +0200] to event
2019-06-10 23:32:04.366328 [DEBUG] switch_channel.c:1260 sofia/internal/1007 at 192.168.0.140 EXPORTING[export_vars] [dialed_extension]=[1008] to event
2019-06-10 23:32:04.366328 [DEBUG] switch_ivr_originate.c:2209 Parsing global variables
2019-06-10 23:32:04.366328 [DEBUG] switch_channel.c:1260 sofia/internal/1007 at 192.168.0.140 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 10 Jun 2019 23:32:04 +0200] to event
2019-06-10 23:32:04.366328 [DEBUG] switch_channel.c:1260 sofia/internal/1007 at 192.168.0.140 EXPORTING[export_vars] [dialed_extension]=[1008] to event
2019-06-10 23:32:04.366328 [DEBUG] switch_ivr_originate.c:2209 Parsing global variables
2019-06-10 23:32:04.366328 [NOTICE] switch_channel.c:1114 New Channel sofia/internal/1008 at 192.168.0.65:2050 [ef2108eb-eb24-4f8d-8675-062f0c66df8d]
2019-06-10 23:32:04.366328 [DEBUG] mod_sofia.c:5032 (sofia/internal/1008 at 192.168.0.65:2050) State Change CS_NEW -> CS_INIT
2019-06-10 23:32:04.366328 [NOTICE] switch_ivr_originate.c:2949 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_INIT (Cur 2 Tot 9)
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1008 at 192.168.0.65:2050) State INIT
2019-06-10 23:32:04.386326 [DEBUG] mod_sofia.c:93 sofia/internal/1008 at 192.168.0.65:2050 SOFIA INIT
2019-06-10 23:32:04.386326 [DEBUG] sofia_glue.c:1315 sofia/internal/1008 at 192.168.0.65:2050 sending invite version: 1.8.6 -7-93b4c92e75 64bit
Local SDP:
v=0
o=FreeSWITCH 1560184610 1560184611 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 17714 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
send 1286 bytes to udp/[192.168.0.65]:2050 at 23:32:04.836347:
------------------------------------------------------------------------
INVITE sip:1008 at 192.168.0.65:2050;line=toh3yju6 SIP/2.0
Via: SIP/2.0/UDP 93.86.XX.XX;rport;branch=z9hG4bK5mc3K1Ut7cp4N
Max-Forwards: 69
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 INVITE
Contact: <sip:mod_sofia at 93.86.XX.XX:5060>
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 270
X-Serialnumber: 00041335F375
P-Key-Flags: keys="3"
X-FS-Support: update_display,send_info
Remote-Party-ID: "Extension 1007" <sip:1007 at 192.168.0.140>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1560184610 1560184611 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 17714 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1008 at 192.168.0.65:2050 Standard INIT
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1008 at 192.168.0.65:2050) State Change CS_INIT -> CS_ROUTING
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1008 at 192.168.0.65:2050) State INIT going to sleep
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_ROUTING (Cur 2 Tot 9)
2019-06-10 23:32:04.386326 [DEBUG] sofia.c:7323 Channel sofia/internal/1008 at 192.168.0.65:2050 entering state [calling][0]
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1008 at 192.168.0.65:2050) State ROUTING
2019-06-10 23:32:04.386326 [DEBUG] mod_sofia.c:154 sofia/internal/1008 at 192.168.0.65:2050 SOFIA ROUTING
2019-06-10 23:32:04.386326 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1008 at 192.168.0.65:2050) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1008 at 192.168.0.65:2050) State ROUTING going to sleep
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 9)
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1008 at 192.168.0.65:2050) State CONSUME_MEDIA
2019-06-10 23:32:04.386326 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1008 at 192.168.0.65:2050) State CONSUME_MEDIA going to sleep
recv 395 bytes from udp/[192.168.0.65]:2050 at 23:32:04.869187:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK5mc3K1Ut7cp4N;received=192.168.0.140
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 INVITE
Contact: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;reg-id=1
Content-Length: 0
------------------------------------------------------------------------
recv 538 bytes from udp/[192.168.0.65]:2050 at 23:32:04.899100:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK5mc3K1Ut7cp4N;received=192.168.0.140
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 INVITE
Contact: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;reg-id=1
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE
Allow-Events: talk, hold, refer, call-info
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:04.446361 [DEBUG] sofia.c:7323 Channel sofia/internal/1008 at 192.168.0.65:2050 entering state [proceeding][180]
2019-06-10 23:32:04.446361 [NOTICE] sofia.c:7433 Ring-Ready sofia/internal/1008 at 192.168.0.65:2050!
2019-06-10 23:32:04.446361 [DEBUG] switch_channel.c:3398 (sofia/internal/1008 at 192.168.0.65:2050) Callstate Change DOWN -> RINGING
2019-06-10 23:32:04.466328 [INFO] switch_ivr_originate.c:1246 Sending early media
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_256_CM_HMAC_SHA1_32]alias=[AES_CM_256_HMAC_SHA1_32] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_192_CM_HMAC_SHA1_32]alias=[AES_CM_192_HMAC_SHA1_32] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_CM_128_HMAC_SHA1_32]alias=[] in [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1813 Found suite AES_CM_128_HMAC_SHA1_32
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1883 Set Remote Key [1 AES_CM_128_HMAC_SHA1_32 inline:HRdV0SVJ7FzedOhJPiNrKg7sZCaMbf20cJgpVImd]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:1209 Set Local audio crypto Key [1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:99:8000:20:0:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:99:8000:20:0:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:99:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G726-32:99:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[opus:116:48000:20:0:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5427 Set telephone-event payload to 101 at 8000
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/1007 at 192.168.0.140 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-06-10 23:32:04.466328 [DEBUG] switch_core_codec.c:111 sofia/internal/1007 at 192.168.0.140 Original read codec set to PCMU:0
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5770 Set telephone-event payload to 101 at 8000
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:5828 sofia/internal/1007 at 192.168.0.140 Set 2833 dtmf send payload to 101 recv payload to 101
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:8568 AUDIO RTP [sofia/internal/1007 at 192.168.0.140] 192.168.0.140 port 30908 -> 192.168.0.66 port 60750 codec: 0 ms: 20
2019-06-10 23:32:04.466328 [DEBUG] switch_rtp.c:4349 Starting timer [soft] 160 bytes per 20ms
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:8875 sofia/internal/1007 at 192.168.0.140 Set 2833 dtmf send payload to 101
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:8882 sofia/internal/1007 at 192.168.0.140 Set 2833 dtmf receive payload to 101
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:8905 sofia/internal/1007 at 192.168.0.140 Set rtp dtmf delay to 40
2019-06-10 23:32:04.466328 [INFO] switch_rtp.c:4153 Activating audio Secure RTP SEND
2019-06-10 23:32:04.466328 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_32
2019-06-10 23:32:04.466328 [INFO] switch_rtp.c:4131 Activating audio Secure RTP RECV
2019-06-10 23:32:04.466328 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_32
2019-06-10 23:32:04.466328 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1007 at 192.168.0.140!
2019-06-10 23:32:04.466328 [DEBUG] switch_channel.c:3526 (sofia/internal/1007 at 192.168.0.140) Callstate Change RINGING -> EARLY
2019-06-10 23:32:04.466328 [DEBUG] switch_core_media.c:8551 Audio params are unchanged for sofia/internal/1007 at 192.168.0.140.
2019-06-10 23:32:04.466328 [DEBUG] mod_sofia.c:2516 Ring SDP:
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
send 1274 bytes to udp/[192.168.0.66]:2048 at 23:32:04.923921:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "1008" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
2019-06-10 23:32:04.466328 [DEBUG] sofia.c:7323 Channel sofia/internal/1007 at 192.168.0.140 entering state [early][183]
2019-06-10 23:32:04.466328 [DEBUG] switch_ivr_originate.c:1304 Raw Codec Activation Success L16 at 8000hz 1 channel 20ms
2019-06-10 23:32:04.466328 [DEBUG] switch_core_codec.c:223 sofia/internal/1007 at 192.168.0.140 Push codec L16:100
2019-06-10 23:32:04.466328 [DEBUG] switch_ivr_originate.c:1378 Play Ringback Tone [%(2000,4000,440,480)]
2019-06-10 23:32:04.666336 [DEBUG] switch_rtp.c:7604 Correct audio ip/port confirmed.
recv 538 bytes from udp/[192.168.0.65]:2050 at 23:32:05.408697:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK5mc3K1Ut7cp4N;received=192.168.0.140
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 INVITE
Contact: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;reg-id=1
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE
Allow-Events: talk, hold, refer, call-info
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:04.946335 [DEBUG] sofia.c:7323 Channel sofia/internal/1008 at 192.168.0.65:2050 entering state [proceeding][180]
recv 538 bytes from udp/[192.168.0.65]:2050 at 23:32:06.418708:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK5mc3K1Ut7cp4N;received=192.168.0.140
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 INVITE
Contact: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;reg-id=1
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE
Allow-Events: talk, hold, refer, call-info
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:05.966335 [DEBUG] sofia.c:7323 Channel sofia/internal/1008 at 192.168.0.65:2050 entering state [proceeding][180]
recv 911 bytes from udp/[192.168.0.65]:2050 at 23:32:06.552003:
------------------------------------------------------------------------
SIP/2.0 200 Ok
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK5mc3K1Ut7cp4N;received=192.168.0.140
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 INVITE
Contact: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;reg-id=1
User-Agent: snom320/8.4.35
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Content-Type: application/sdp
Content-Length: 268
v=0
o=root 2084871394 2084871395 IN IP4 192.168.0.65
s=call
c=IN IP4 192.168.0.65
t=0 0
m=audio 57948 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
2019-06-10 23:32:06.086339 [DEBUG] sofia.c:7323 Channel sofia/internal/1008 at 192.168.0.65:2050 entering state [completing][200]
2019-06-10 23:32:06.086339 [DEBUG] sofia.c:7333 Remote SDP:
v=0
o=root 2084871394 2084871395 IN IP4 192.168.0.65
s=call
c=IN IP4 192.168.0.65
t=0 0
m=audio 57948 RTP/AVP 0 8 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2019-06-10 23:32:06.086339 [NOTICE] sofia.c:7336 Pre-Answer sofia/internal/1008 at 192.168.0.65:2050!
2019-06-10 23:32:06.086339 [DEBUG] switch_channel.c:3526 (sofia/internal/1008 at 192.168.0.65:2050) Callstate Change RINGING -> EARLY
send 398 bytes to udp/[192.168.0.65]:2050 at 23:32:06.556037:
------------------------------------------------------------------------
ACK sip:1008 at 192.168.0.65:2050;line=toh3yju6 SIP/2.0
Via: SIP/2.0/UDP 93.86.XX.XX;rport;branch=z9hG4bK6X5UNvcy4NcQH
Max-Forwards: 70
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547370 ACK
Contact: <sip:mod_sofia at 93.86.XX.XX:5060>
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:06.106386 [DEBUG] sofia.c:7323 Channel sofia/internal/1008 at 192.168.0.65:2050 entering state [ready][200]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5427 Set telephone-event payload to 101 at 8000
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/1008 at 192.168.0.65:2050 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-06-10 23:32:06.106386 [DEBUG] switch_core_codec.c:111 sofia/internal/1008 at 192.168.0.65:2050 Original read codec set to PCMU:0
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5770 Set telephone-event payload to 101 at 8000
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:5828 sofia/internal/1008 at 192.168.0.65:2050 Set 2833 dtmf send payload to 101 recv payload to 101
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:8568 AUDIO RTP [sofia/internal/1008 at 192.168.0.65:2050] 192.168.0.140 port 17714 -> 192.168.0.65 port 57948 codec: 0 ms: 20
2019-06-10 23:32:06.106386 [DEBUG] switch_rtp.c:4349 Starting timer [soft] 160 bytes per 20ms
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:8875 sofia/internal/1008 at 192.168.0.65:2050 Set 2833 dtmf send payload to 101
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:8882 sofia/internal/1008 at 192.168.0.65:2050 Set 2833 dtmf receive payload to 101
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:8905 sofia/internal/1008 at 192.168.0.65:2050 Set rtp dtmf delay to 40
2019-06-10 23:32:06.106386 [NOTICE] sofia.c:8461 Channel [sofia/internal/1008 at 192.168.0.65:2050] has been answered
2019-06-10 23:32:06.106386 [DEBUG] switch_channel.c:3825 (sofia/internal/1008 at 192.168.0.65:2050) Callstate Change EARLY -> ACTIVE
2019-06-10 23:32:06.106386 [DEBUG] switch_core_codec.c:248 sofia/internal/1007 at 192.168.0.140 Restore previous codec PCMU:0.
2019-06-10 23:32:06.106386 [DEBUG] switch_core_media.c:8551 Audio params are unchanged for sofia/internal/1007 at 192.168.0.140.
2019-06-10 23:32:06.106386 [DEBUG] mod_sofia.c:893 Local SDP sofia/internal/1007 at 192.168.0.140:
v=0
o=FreeSWITCH 1560171416 1560171418 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:06.564327:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
2019-06-10 23:32:06.106386 [DEBUG] sofia.c:7323 Channel sofia/internal/1007 at 192.168.0.140 entering state [completed][200]
2019-06-10 23:32:06.106386 [NOTICE] switch_ivr_originate.c:3745 Channel [sofia/internal/1007 at 192.168.0.140] has been answered
2019-06-10 23:32:06.106386 [DEBUG] switch_channel.c:3825 (sofia/internal/1007 at 192.168.0.140) Callstate Change EARLY -> ACTIVE
2019-06-10 23:32:06.106386 [DEBUG] switch_ivr_originate.c:3803 Originate Resulted in Success: [sofia/internal/1008 at 192.168.0.65:2050]
2019-06-10 23:32:06.106386 [DEBUG] switch_ivr_originate.c:3803 Originate Resulted in Success: [sofia/internal/1008 at 192.168.0.65:2050]
2019-06-10 23:32:06.106386 [DEBUG] switch_ivr_bridge.c:1795 (sofia/internal/1008 at 192.168.0.65:2050) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2019-06-10 23:32:06.106386 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 9)
2019-06-10 23:32:06.106386 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1008 at 192.168.0.65:2050) State EXCHANGE_MEDIA
2019-06-10 23:32:06.106386 [DEBUG] mod_sofia.c:657 SOFIA EXCHANGE_MEDIA
2019-06-10 23:32:06.166346 [DEBUG] switch_rtp.c:7604 Correct audio ip/port confirmed.
2019-06-10 23:32:06.266338 [DEBUG] switch_rtp.c:7604 Correct audio ip/port confirmed.
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:07.064545:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:08.065553:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:10.066615:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
freeswitch at deb9>
freeswitch at deb9>
freeswitch at deb9>
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:14.066821:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:18.067037:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:22.067209:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:26.067420:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:30.068634:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:34.069263:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
freeswitch at deb9>
freeswitch at deb9>
send 1281 bytes to udp/[192.168.0.66]:2048 at 23:32:38.069488:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.66:2048;branch=z9hG4bK-6blzopopy6u8;rport=2048
From: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
To: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 2 INVITE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
Call-Info: <sip:192.168.0.140>;appearance-index=1
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 3600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 329
Remote-Party-ID: "Outbound Call" <sip:1008 at 192.168.0.140>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1560171416 1560171417 IN IP4 192.168.0.140
s=FreeSWITCH
c=IN IP4 192.168.0.140
t=0 0
m=audio 30908 RTP/SAVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:aE2vytPpfYFzwCXO0x920fS8/mpTiphai6b5PyCa
m=audio 0 RTP/AVP 19
------------------------------------------------------------------------
send 626 bytes to udp/[192.168.0.66]:2048 at 23:32:38.563696:
------------------------------------------------------------------------
BYE sip:1007 at 192.168.0.66:2048;line=qws41d8u SIP/2.0
Via: SIP/2.0/UDP 93.86.XX.XX;rport;branch=z9hG4bK76ymQQX11y29c
Max-Forwards: 70
From: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
To: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 5547387 BYE
Contact: <sip:1008 at 93.86.XX.XX:5060;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Reason: SIP;cause=408;text="ACK Timeout"
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:38.126337 [DEBUG] sofia.c:7323 Channel sofia/internal/1007 at 192.168.0.140 entering state [terminating][0]
2019-06-10 23:32:38.126337 [NOTICE] sofia.c:8516 Hangup sofia/internal/1007 at 192.168.0.140 [CS_EXECUTE] [NORMAL_UNSPECIFIED]
2019-06-10 23:32:38.126337 [DEBUG] switch_ivr_bridge.c:831 sofia/internal/1007 at 192.168.0.140 ending bridge by request from read function
2019-06-10 23:32:38.126337 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1007 at 192.168.0.140]
2019-06-10 23:32:38.146339 [DEBUG] switch_ivr_bridge.c:825 sofia/internal/1007 at 192.168.0.140 ending bridge by request from write function
2019-06-10 23:32:38.146339 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1008 at 192.168.0.65:2050]
2019-06-10 23:32:38.146339 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/internal/1008 at 192.168.0.65:2050 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1008 at 192.168.0.65:2050) State EXCHANGE_MEDIA going to sleep
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_HANGUP (Cur 2 Tot 9)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/1008 at 192.168.0.65:2050) Callstate Change ACTIVE -> HANGUP
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1008 at 192.168.0.65:2050) State HANGUP
2019-06-10 23:32:38.146339 [DEBUG] mod_sofia.c:460 Channel sofia/internal/1008 at 192.168.0.65:2050 hanging up, cause: NORMAL_CLEARING
2019-06-10 23:32:38.146339 [DEBUG] mod_sofia.c:513 Sending BYE to sofia/internal/1008 at 192.168.0.65:2050
send 604 bytes to udp/[192.168.0.65]:2050 at 23:32:38.598995:
------------------------------------------------------------------------
BYE sip:1008 at 192.168.0.65:2050;line=toh3yju6 SIP/2.0
Via: SIP/2.0/UDP 93.86.XX.XX;rport;branch=z9hG4bK8FrDSje5y7rvr
Max-Forwards: 70
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547371 BYE
User-Agent: FreeSWITCH-mod_sofia/1.8.6-7-93b4c92e75~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
------------------------------------------------------------------------
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1008 at 192.168.0.65:2050 Standard HANGUP, cause: NORMAL_CLEARING
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1008 at 192.168.0.65:2050) State HANGUP going to sleep
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1008 at 192.168.0.65:2050) State Change CS_HANGUP -> CS_REPORTING
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_REPORTING (Cur 2 Tot 9)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1008 at 192.168.0.65:2050) State REPORTING
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1008 at 192.168.0.65:2050 Standard REPORTING, cause: NORMAL_CLEARING
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1008 at 192.168.0.65:2050) State REPORTING going to sleep
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1008 at 192.168.0.65:2050) State Change CS_REPORTING -> CS_DESTROY
2019-06-10 23:32:38.146339 [DEBUG] switch_core_session.c:1726 Session 9 (sofia/internal/1008 at 192.168.0.65:2050) Locked, Waiting on external entities
2019-06-10 23:32:38.146339 [DEBUG] switch_ivr_bridge.c:1897 sofia/internal/1007 at 192.168.0.140 skip receive message [UNBRIDGE] (channel is hungup already)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_session.c:2905 sofia/internal/1007 at 192.168.0.140 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1007 at 192.168.0.140) State EXECUTE going to sleep
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_HANGUP (Cur 2 Tot 9)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/1007 at 192.168.0.140) Callstate Change ACTIVE -> HANGUP
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1007 at 192.168.0.140) State HANGUP
2019-06-10 23:32:38.146339 [DEBUG] mod_sofia.c:460 Channel sofia/internal/1007 at 192.168.0.140 hanging up, cause: NORMAL_UNSPECIFIED
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1007 at 192.168.0.140 Standard HANGUP, cause: NORMAL_UNSPECIFIED
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/1007 at 192.168.0.140) State HANGUP going to sleep
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1007 at 192.168.0.140) State Change CS_HANGUP -> CS_REPORTING
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_REPORTING (Cur 2 Tot 9)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1007 at 192.168.0.140) State REPORTING
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1007 at 192.168.0.140 Standard REPORTING, cause: NORMAL_UNSPECIFIED
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/1007 at 192.168.0.140) State REPORTING going to sleep
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1007 at 192.168.0.140) State Change CS_REPORTING -> CS_DESTROY
2019-06-10 23:32:38.146339 [DEBUG] switch_core_session.c:1726 Session 8 (sofia/internal/1007 at 192.168.0.140) Locked, Waiting on external entities
2019-06-10 23:32:38.146339 [NOTICE] switch_core_session.c:1744 Session 8 (sofia/internal/1007 at 192.168.0.140) Ended
2019-06-10 23:32:38.146339 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/1007 at 192.168.0.140 [CS_DESTROY]
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/1007 at 192.168.0.140) Running State Change CS_DESTROY (Cur 1 Tot 9)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1007 at 192.168.0.140) State DESTROY
2019-06-10 23:32:38.146339 [DEBUG] mod_sofia.c:365 sofia/internal/1007 at 192.168.0.140 SOFIA DESTROY
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1007 at 192.168.0.140 Standard DESTROY
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1007 at 192.168.0.140) State DESTROY going to sleep
2019-06-10 23:32:38.146339 [NOTICE] switch_core_session.c:1744 Session 9 (sofia/internal/1008 at 192.168.0.65:2050) Ended
2019-06-10 23:32:38.146339 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/1008 at 192.168.0.65:2050 [CS_DESTROY]
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/1008 at 192.168.0.65:2050) Running State Change CS_DESTROY (Cur 0 Tot 9)
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1008 at 192.168.0.65:2050) State DESTROY
2019-06-10 23:32:38.146339 [DEBUG] mod_sofia.c:365 sofia/internal/1008 at 192.168.0.65:2050 SOFIA DESTROY
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1008 at 192.168.0.65:2050 Standard DESTROY
2019-06-10 23:32:38.146339 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/1008 at 192.168.0.65:2050) State DESTROY going to sleep
recv 531 bytes from udp/[192.168.0.66]:2048 at 23:32:38.610924:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK76ymQQX11y29c;received=192.168.0.140
From: <sip:1008 at 192.168.0.140;user=phone>;tag=N3ZyFcHUB5U1N
To: "Test 7" <sip:1007 at 192.168.0.140>;tag=p2g6ntoftq
Call-ID: 3c268bbf732f-0c0rr7bh0w4l
CSeq: 5547387 BYE
Contact: <sip:1007 at 192.168.0.66:2048;line=qws41d8u>;reg-id=1
User-Agent: snom320/8.4.35
RTP-RxStat: Total_Rx_Pkts=1676,Rx_Pkts=0,Rx_Pkts_Lost=1,Remote_Rx_Pkts_Lost=0
RTP-TxStat: Total_Tx_Pkts=1676,Tx_Pkts=1676,Remote_Tx_Pkts=0
Content-Length: 0
------------------------------------------------------------------------
recv 557 bytes from udp/[192.168.0.65]:2050 at 23:32:38.640007:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 93.86.XX.XX;rport=5060;branch=z9hG4bK8FrDSje5y7rvr;received=192.168.0.140
From: "Extension 1007" <sip:1007 at 192.168.0.140>;tag=pcSQH71y8DjmH
To: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;tag=emgd2q017e
Call-ID: 085e7d69-066a-1238-3399-52540028724f
CSeq: 5547371 BYE
Contact: <sip:1008 at 192.168.0.65:2050;line=toh3yju6>;reg-id=1
User-Agent: snom320/8.4.35
RTP-RxStat: Total_Rx_Pkts=1597,Rx_Pkts=0,Rx_Pkts_Lost=1,Remote_Rx_Pkts_Lost=0
RTP-TxStat: Total_Tx_Pkts=1599,Tx_Pkts=1599,Remote_Tx_Pkts=0
Content-Length: 0
------------------------------------------------------------------------
More information about the FreeSWITCH-users
mailing list