[Freeswitch-users] NAT/VPN DTMF and Audio Issue
Kieran Hackshall
kbhackshall at gmail.com
Mon Aug 15 06:44:06 MSD 2016
We have a Freeswitch instance setup and it is working for calls using SIP
to carriers. The current solution we have uses a NAT server to present a
single IP to carriers. The issue we are facing now is a new carrier that
required us to connect via VPN and then handle RTP over the internet via a
NAT.
Currently we have setup the new requirement and can make outbound calls and
play and hear media, however, DTMF is not working. Also when a call is
transferred no audio is present on either side.
One major difference I can see between using our current carriers that are
woking and the new one is that I cannot see in the Freeswitch log 'RTP
Correct ip/port confirmed'. Not too sure if this indicates there is an
issue or not.
Our Freeswitch configs are vanilla except that we set the NAT external IP
for SIP and RTP in the vars.xml
I have attached a Freeswitch log with additional SIP tracing, any help in
resolving this issue would be greatly appreciated.
Thanks,
Kieran
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20160815/6c1ddcea/attachment-0001.html
-------------- next part --------------
2016-08-15 01:50:25.400493 [DEBUG] switch_ivr_originate.c:2100 Parsing global variables
2016-08-15 01:50:25.400493 [DEBUG] switch_event.c:1698 Parsing variable [origination_caller_id_name]=[xxx61452594]
2016-08-15 01:50:25.400493 [DEBUG] switch_event.c:1698 Parsing variable [ignore_early_media]=[true]
2016-08-15 01:50:25.400493 [NOTICE] switch_channel.c:1075 New Channel sofia/external/xxx98645055 [bf436d68-1516-41cc-a080-12866b00e68b]
2016-08-15 01:50:25.400493 [DEBUG] mod_sofia.c:4701 (sofia/external/xxx98645055) State Change CS_NEW -> CS_INIT
2016-08-15 01:50:25.400493 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:472 (sofia/external/xxx98645055) Running State Change CS_INIT
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:512 (sofia/external/xxx98645055) State INIT
2016-08-15 01:50:25.400493 [DEBUG] mod_sofia.c:87 sofia/external/xxx98645055 SOFIA INIT
2016-08-15 01:50:25.400493 [DEBUG] sofia_glue.c:1236 sofia/external/xxx98645055 sending invite version: 1.4.19 -5-1 64bit
Local SDP:
v=0
o=FreeSWITCH 1471167765 1471167766 IN IP4 xxx.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 58060 RTP/AVP 0 8 3 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
send 1141 bytes to udp/[xxx.xxx.xxx.xx]:50619 at 01:50:25.417429:
------------------------------------------------------------------------
INVITE sip:xxx98645055 at xxx.xxx.xxx.xx:50619 SIP/2.0
freeswitch at internal> Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5070;rport;branch=z9hG4bKKFpBymXSD7QpF
Max-Forwards: 70
From: "xxx61452594" <sip:FreeSWITCH at xxx.xxx.xxx.xx:50619>;tag=jve4DHXF2BZeS
To: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 95276848 INVITE
Contact: <sip:gw+pivotel-au at xxx.xxx.xxx.xxx:5070;transport=udp;gw=pivotel-au>
User-Agent: FreeSWITCH-mod_sofia/1.4.19-5-1~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 276
X-FS-Support: update_display,send_info
Remote-Party-ID: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:50619>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1471167765 1471167766 IN IP4 xxx.xxx.xxx.xxx
s=FreeSWITCH
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 58060 RTP/AVP 0 8 3 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2016-08-15 01:50:25.400493 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:40 sofia/external/xxx98645055 Standard INIT
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:48 (sofia/external/xxx98645055) State Change CS_INIT -> CS_ROUTING
2016-08-15 01:50:25.400493 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:512 (sofia/external/xxx98645055) State INIT going to sleep
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:472 (sofia/external/xxx98645055) Running State Change CS_ROUTING
2016-08-15 01:50:25.400493 [DEBUG] sofia.c:6627 Channel sofia/external/xxx98645055 entering state [calling][0]
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:528 (sofia/external/xxx98645055) State ROUTING
2016-08-15 01:50:25.400493 [DEBUG] mod_sofia.c:123 sofia/external/xxx98645055 SOFIA ROUTING
2016-08-15 01:50:25.400493 [DEBUG] switch_ivr_originate.c:67 (sofia/external/xxx98645055) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2016-08-15 01:50:25.400493 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:528 (sofia/external/xxx98645055) State ROUTING going to sleep
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:472 (sofia/external/xxx98645055) Running State Change CS_CONSUME_MEDIA
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:547 (sofia/external/xxx98645055) State CONSUME_MEDIA
2016-08-15 01:50:25.400493 [DEBUG] switch_core_state_machine.c:547 (sofia/external/xxx98645055) State CONSUME_MEDIA going to sleep
recv 331 bytes from udp/[xxx.xxx.xxx.xx]:50619 at 01:50:25.582325:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP xxx.xxx.xxx.xx:5060;branch=z9hG4bKKFpBymXSD7QpF;rport=50619;received=10.22.160.28
From: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:5060>;tag=jve4DHXF2BZeS
To: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 95276848 INVITE
Content-Length: 0
------------------------------------------------------------------------
recv 771 bytes from udp/[xxx.xxx.xxx.xx]:50619 at 01:50:29.540563:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP xxx.xxx.xxx.xx:5060;branch=z9hG4bKKFpBymXSD7QpF;rport=50619;received=10.22.160.28
From: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:5060>;tag=jve4DHXF2BZeS
To: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>;tag=2421515
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 95276848 INVITE
Contact: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>
Content-Type: application/sdp
Allow: INVITE
Allow: ACK
Allow: BYE
Allow: CANCEL
Allow: INFO
Allow: PRACK
Allow: UPDATE
Content-Length: 238
v=0
o=genband 323719168 1471225826 IN IP4 xxx.xxx.xxx.xx
s=-
c=IN IP4 xxx.xxx.xxx.xx
t=0 0
m=audio 36256 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
------------------------------------------------------------------------
2016-08-15 01:50:29.540514 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:29.540514 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:29.540514 [DEBUG] sofia.c:6627 Channel sofia/external/xxx98645055 entering state [proceeding][183]
2016-08-15 01:50:29.540514 [DEBUG] sofia.c:6637 Remote SDP:
v=0
o=genband 323719168 1471225826 IN IP4 xxx.xxx.xxx.xx
s=-
c=IN IP4 xxx.xxx.xxx.xx
t=0 0
m=audio 36256 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:3678 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:3678 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:3733 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:3678 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:3594 Set telephone-event payload to 101
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:2507 Set Codec sofia/external/xxx98645055 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2016-08-15 01:50:29.540514 [DEBUG] switch_core_codec.c:111 sofia/external/xxx98645055 Original read codec set to PCMA:8
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:3932 Set 2833 dtmf send payload to 101
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:5177 AUDIO RTP [sofia/external/xxx98645055] 172.22.1.10 port 58060 -> xxx.xxx.xxx.xx port 36256 codec: 8 ms: 20
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:3569 Starting timer [soft] 160 bytes per 20ms
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: START SESSION INITIALIZATION. sID=1.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: ZID=306166303733613464366363.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: Loading User's profile:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: allowclear: OFF
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: autosecure: ON
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: disclose_bit: OFF
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: signal. role: Initiator
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: TTL: 4294967295
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: SAS schemes:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 B256
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 B32
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: Ciphers:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 AES3
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 AES1
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: PK schemes:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 EC25
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 DH3k
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 DH2k
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 Mult
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: ATL:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 HS32
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: Hashes:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 S256
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: Session initialization - DONE. sID=1.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: ATTACH NEW STREAM to sID=1:
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: Empty slot was found - initializing new stream with ID=1.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: Preparing ZRTP Hello according to the Session profile.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp main]: ATTACH NEW STREAM - DONE.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: START STREAM ID=1 mode=CLEAR state=ACTIVE.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=1 CLEAR switching <ACTIVE> ---> <START>.
2016-08-15 01:50:29.540514 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38308 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:5475 Set 2833 dtmf send payload to 101
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:5481 Set 2833 dtmf receive payload to 101
2016-08-15 01:50:29.540514 [DEBUG] switch_core_media.c:5503 sofia/external/xxx98645055 Set rtp dtmf delay to 40
2016-08-15 01:50:29.540514 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/xxx98645055!
2016-08-15 01:50:29.540514 [DEBUG] switch_channel.c:3419 (sofia/external/xxx98645055) Callstate Change DOWN -> EARLY
2016-08-15 01:50:29.600487 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38309 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:29.700487 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38310 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:29.900489 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38311 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:30.100490 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38312 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:30.300486 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO_ZRTP_QUICK event. ID=1
2016-08-15 01:50:30.300486 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38313 size=144. Stream 1:CLEAR:START
recv 762 bytes from udp/[xxx.xxx.xxx.xx]:50619 at 01:50:30.493757:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP xxx.xxx.xxx.xx:5060;branch=z9hG4bKKFpBymXSD7QpF;rport=50619;received=10.22.160.28
From: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:5060>;tag=jve4DHXF2BZeS
To: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>;tag=2421515
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 95276848 INVITE
Contact: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>
Content-Type: application/sdp
Allow: INVITE
Allow: ACK
Allow: BYE
Allow: CANCEL
Allow: INFO
Allow: PRACK
Allow: UPDATE
Content-Length: 238
v=0
o=genband 323719168 1471225826 IN IP4 xxx.xxx.xxx.xx
s=-
c=IN IP4 xxx.xxx.xxx.xx
t=0 0
m=audio 36256 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
------------------------------------------------------------------------
2016-08-15 01:50:30.480494 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:30.480494 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:30.480494 [DEBUG] sofia.c:6627 Channel sofia/external/xxx98645055 entering state [proceeding][180]
2016-08-15 01:50:30.480494 [DEBUG] sofia.c:6634 Duplicate SDP
v=0
o=genband 323719168 1471225826 IN IP4 xxx.xxx.xxx.xx
s=-
c=IN IP4 xxx.xxx.xxx.xx
t=0 0
m=audio 36256 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:3678 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:3678 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:3733 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:3678 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:3594 Set telephone-event payload to 101
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:3932 Set 2833 dtmf send payload to 101
2016-08-15 01:50:30.480494 [DEBUG] switch_core_media.c:5160 Audio params are unchanged for sofia/external/xxx98645055.
2016-08-15 01:50:30.500493 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38314 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:30.700492 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38315 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:30.900498 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38316 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:31.100492 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38317 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:31.300493 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38318 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:31.500493 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38319 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:31.700524 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38320 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:31.900482 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38321 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:32.100492 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38322 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:32.300488 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38323 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:32.500492 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38324 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:32.700489 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38325 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:32.900492 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38326 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:33.100492 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Send <HELLO> ssrc=1503312829 seq=38327 size=144. Stream 1:CLEAR:START
2016-08-15 01:50:33.300482 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=1
2016-08-15 01:50:33.300482 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=1 CLEAR switching <START> ---> <NOZRTP>.
recv 776 bytes from udp/[xxx.xxx.xxx.xx]:50619 at 01:50:33.484919:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xx:5060;branch=z9hG4bKKFpBymXSD7QpF;rport=50619;received=10.22.160.28
From: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:5060>;tag=jve4DHXF2BZeS
To: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>;tag=2421515
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 95276848 INVITE
Contact: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>
Content-Type: application/sdp
Allow: INVITE
Allow: ACK
Allow: BYE
Allow: CANCEL
Allow: INFO
Allow: PRACK
Allow: UPDATE
Supported: 100rel
Content-Length: 238
v=0
o=genband 323719168 1471225826 IN IP4 xxx.xxx.xxx.xx
s=-
c=IN IP4 xxx.xxx.xxx.xx
t=0 0
m=audio 36256 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
------------------------------------------------------------------------
2016-08-15 01:50:33.480488 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:33.480488 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:33.480488 [DEBUG] sofia.c:6627 Channel sofia/external/xxx98645055 entering state [completing][200]
2016-08-15 01:50:33.480488 [DEBUG] sofia.c:6634 Duplicate SDP
v=0
o=genband 323719168 1471225826 IN IP4 xxx.xxx.xxx.xx
s=-
c=IN IP4 xxx.xxx.xxx.xx
t=0 0
m=audio 36256 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
send 441 bytes to udp/[xxx.xxx.xxx.xx]:50619 at 01:50:33.485920:
------------------------------------------------------------------------
ACK sip:xxx98645055 at xxx.xxx.xxx.xx:50619 SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5070;rport;branch=z9hG4bKmrF4ZFeXage9a
Max-Forwards: 70
From: "xxx61452594" <sip:FreeSWITCH at xxx.xxx.xxx.xx:50619>;tag=jve4DHXF2BZeS
To: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>;tag=2421515
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 95276848 ACK
Contact: <sip:gw+pivotel-au at xxx.xxx.xxx.xxx:5070;transport=udp;gw=pivotel-au>
Content-Length: 0
------------------------------------------------------------------------
2016-08-15 01:50:33.480488 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:33.480488 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:33.480488 [DEBUG] sofia.c:6627 Channel sofia/external/xxx98645055 entering state [ready][200]
2016-08-15 01:50:33.480488 [NOTICE] sofia.c:7429 Channel [sofia/external/xxx98645055] has been answered
2016-08-15 01:50:33.480488 [DEBUG] switch_channel.c:3711 (sofia/external/xxx98645055) Callstate Change EARLY -> ACTIVE
2016-08-15 01:50:33.480488 [DEBUG] switch_ivr_originate.c:3577 Originate Resulted in Success: [sofia/external/xxx98645055]
2016-08-15 01:50:33.480488 [INFO] switch_channel.c:3082 sofia/external/xxx98645055 Flipping CID from "xxx61452594" <0000000000> to "Outbound Call" <xxx98645055>
2016-08-15 01:50:33.480488 [DEBUG] mod_commands.c:4469 (sofia/external/xxx98645055) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2016-08-15 01:50:33.480488 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:33.480488 [DEBUG] switch_core_state_machine.c:472 (sofia/external/xxx98645055) Running State Change CS_EXECUTE
2016-08-15 01:50:33.480488 [DEBUG] switch_core_state_machine.c:535 (sofia/external/xxx98645055) State EXECUTE
2016-08-15 01:50:33.480488 [DEBUG] mod_sofia.c:178 sofia/external/xxx98645055 SOFIA EXECUTE
2016-08-15 01:50:33.480488 [DEBUG] switch_core_state_machine.c:258 sofia/external/xxx98645055 Standard EXECUTE
EXECUTE sofia/external/xxx98645055 park()
recv 433 bytes from udp/[xxx.xxx.xxx.xx]:50619 at 01:50:40.914762:
------------------------------------------------------------------------
BYE sip:0000000000 at xxx.xxx.xxx.xx:5060;transport=udp;gw=pivotel-au SIP/2.0
Via: SIP/2.0/UDP xxx.xxx.xxx.xx:50619;branch=z9hG4bK-57069baf-23601292
From: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>;tag=2421515
To: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:5060>;tag=jve4DHXF2BZeS
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 1 BYE
Max-forwards: 70
Reason: Q.850; cause=16; text="Normal call clearing"
Content-Length: 0
------------------------------------------------------------------------
2016-08-15 01:50:40.900493 [DEBUG] switch_core_session.c:1061 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:40.920494 [NOTICE] sofia.c:952 Hangup sofia/external/xxx98645055 [CS_EXECUTE] [NORMAL_CLEARING]
2016-08-15 01:50:40.920494 [DEBUG] switch_channel.c:3242 Send signal sofia/external/xxx98645055 [KILL]
2016-08-15 01:50:40.920494 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
send 488 bytes to udp/[xxx.xxx.xxx.xx]:50619 at 01:50:40.922654:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xx:50619;branch=z9hG4bK-57069baf-23601292;rport=50619
From: <sip:xxx98645055 at xxx.xxx.xxx.xx:50619>;tag=2421515
To: "xxx61452594" <sip:0000000000 at xxx.xxx.xxx.xx:5060>;tag=jve4DHXF2BZeS
Call-ID: 79f4f2c5-dd2d-1234-9da4-4201ac16010a
CSeq: 1 BYE
User-Agent: FreeSWITCH-mod_sofia/1.4.19-5-1~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0
------------------------------------------------------------------------
2016-08-15 01:50:40.920494 [DEBUG] switch_core_session.c:2901 sofia/external/xxx98645055 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:535 (sofia/external/xxx98645055) State EXECUTE going to sleep
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:472 (sofia/external/xxx98645055) Running State Change CS_HANGUP
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:735 (sofia/external/xxx98645055) Callstate Change ACTIVE -> HANGUP
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:737 (sofia/external/xxx98645055) State HANGUP
2016-08-15 01:50:40.920494 [DEBUG] mod_sofia.c:413 Channel sofia/external/xxx98645055 hanging up, cause: NORMAL_CLEARING
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:60 sofia/external/xxx98645055 Standard HANGUP, cause: NORMAL_CLEARING
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:737 (sofia/external/xxx98645055) State HANGUP going to sleep
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:504 (sofia/external/xxx98645055) State Change CS_HANGUP -> CS_REPORTING
2016-08-15 01:50:40.920494 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:472 (sofia/external/xxx98645055) Running State Change CS_REPORTING
2016-08-15 01:50:40.920494 [DEBUG] switch_core_state_machine.c:823 (sofia/external/xxx98645055) State REPORTING
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:104 sofia/external/xxx98645055 Standard REPORTING, cause: NORMAL_CLEARING
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:823 (sofia/external/xxx98645055) State REPORTING going to sleep
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:498 (sofia/external/xxx98645055) State Change CS_REPORTING -> CS_DESTROY
2016-08-15 01:50:40.940520 [DEBUG] switch_core_session.c:1396 Send signal sofia/external/xxx98645055 [BREAK]
2016-08-15 01:50:40.940520 [DEBUG] switch_core_session.c:1623 Session 2 (sofia/external/xxx98645055) Locked, Waiting on external entities
2016-08-15 01:50:40.940520 [NOTICE] switch_core_session.c:1641 Session 2 (sofia/external/xxx98645055) Ended
2016-08-15 01:50:40.940520 [NOTICE] switch_core_session.c:1645 Close Channel sofia/external/xxx98645055 [CS_DESTROY]
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:626 (sofia/external/xxx98645055) Running State Change CS_DESTROY
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:636 (sofia/external/xxx98645055) State DESTROY
2016-08-15 01:50:40.940520 [DEBUG] mod_sofia.c:323 sofia/external/xxx98645055 SOFIA DESTROY
2016-08-15 01:50:40.940520 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: STOP STREAM ID=1 mode=CLEAR state=NOZRTP.
2016-08-15 01:50:40.940520 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>.
2016-08-15 01:50:40.940520 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE.
2016-08-15 01:50:40.940520 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE.
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:111 sofia/external/xxx98645055 Standard DESTROY
2016-08-15 01:50:40.940520 [DEBUG] switch_core_state_machine.c:636 (sofia/external/xxx98645055) State DESTROY going to sleep
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list