[Freeswitch-users] can't hear audio when dialing 9198 (Tetris audio test)

Tue May 6 04:24:52 MSD 2014

Thanks to all who commented. Both opening up the UDP RTP ports and setting
the internal profile ext-rtp-ip and ext-sip-ip values to the FreeSwitch
server public IP solved the problem. Now both the Tetris and Echo tests
work.

However, I still have a question. When I compared the logs before and after
I made the change I saw this difference which I account as the reason for
the original problem:

Log before the changes:

8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 2014-05-05 23:54:13.331397 [NOTICE]
sofia_glue.c:4360 Pre-Answer sofia/internal/1007@<FreeSwitch server Public
IP>!
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 2014-05-05 23:54:13.331397 [DEBUG]
switch_channel.c:3368 (sofia/internal/1007@<FreeSwitch server Public IP>)
Callstate Change RINGING -> EARLY
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 2014-05-05 23:54:13.331397 [DEBUG]
mod_sofia.c:866 Local SDP sofia/internal/1007@<FreeSwitch server Public IP>:
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 v=0
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 o=FreeSWITCH 1399305799 1399305800 IN
IP4 <FreeSwitch server Private IP>
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 s=FreeSWITCH
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 c=IN IP4 <FreeSwitch server Private IP>
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 t=0 0
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 m=audio 28254 RTP/AVP 9 101
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 a=rtpmap:9 G722/8000
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 a=rtpmap:101 telephone-event/8000
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 a=fmtp:101 0-16
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 a=ptime:20
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9 a=sendrecv
8f1896d4-d4b0-11e3-98a8-7f053ccdf4d9

Log after the changes:

bc2c05ce-d4b1-11e3-bd7d-6970e278349a 2014-05-06 00:02:38.431536 [NOTICE]
sofia_glue.c:4360 Pre-Answer sofia/internal/1007@<FreeSwitch server Public
IP>!
bc2c05ce-d4b1-11e3-bd7d-6970e278349a 2014-05-06 00:02:38.431536 [DEBUG]
switch_channel.c:3368 (sofia/internal/1007@<FreeSwitch server Public IP>)
Callstate Change RINGING -> EARLY
bc2c05ce-d4b1-11e3-bd7d-6970e278349a 2014-05-06 00:02:38.431536 [DEBUG]
mod_sofia.c:866 Local SDP sofia/internal/1007@<FreeSwitch server Public IP>:
bc2c05ce-d4b1-11e3-bd7d-6970e278349a v=0
bc2c05ce-d4b1-11e3-bd7d-6970e278349a o=FreeSWITCH 1399309520 1399309521 IN
IP4 <FreeSwitch server Public IP>
bc2c05ce-d4b1-11e3-bd7d-6970e278349a s=FreeSWITCH
bc2c05ce-d4b1-11e3-bd7d-6970e278349a c=IN IP4 <FreeSwitch server Public IP>
bc2c05ce-d4b1-11e3-bd7d-6970e278349a t=0 0
bc2c05ce-d4b1-11e3-bd7d-6970e278349a m=audio 25038 RTP/AVP 9 101
bc2c05ce-d4b1-11e3-bd7d-6970e278349a a=rtpmap:9 G722/8000
bc2c05ce-d4b1-11e3-bd7d-6970e278349a a=rtpmap:101 telephone-event/8000
bc2c05ce-d4b1-11e3-bd7d-6970e278349a a=fmtp:101 0-16
bc2c05ce-d4b1-11e3-bd7d-6970e278349a a=ptime:20
bc2c05ce-d4b1-11e3-bd7d-6970e278349a a=sendrecv
bc2c05ce-d4b1-11e3-bd7d-6970e278349a

So the main difference is that the Local SDP has the server's private IP
before I made the changes and then after it has the server's public IP.
However, I don't quite understand what is going on here. Is this some
additional negotiation between the server and client to establish the audio
channel?

Thanks.

Jeff Stark

On Sun, May 4, 2014 at 11:27 PM, Francis <sms at icefire.qza.net.au> wrote:

>  You'll find these two variables in your internal and external profiles,
> try setting them to either STUN (as per the examples in the comments) or
> hard code the IP address:
>
> <param name="ext-rtp-ip" value="$${external_rtp_ip}"/>
> <param name="ext-sip-ip" value="$${external_sip_ip}"/>
>
> This along with opening the correct ports is the best solution I've found
> for double NAT scenarios, but that's installing on bare metal. YMMV.
>
>
>
>
> On 2014-05-06 00:02, Steven Ayre wrote:
>
> Also check the IP in the logged "remote SDP" message (which is before what
> you're posted). Verify that it's an IP actually reachable from the server.
> A common problem is having a client that's behind NAT sending the LAN IP
> which isn't reachable over the internet, rather than it's external IP.
>
>
> On 5 May 2014 14:55, Michael Jerris <mike at jerris.com> wrote:
>
>> do you have udp ports open for rtp?
>>
>>  On May 4, 2014, at 9:03 PM, Jeff Stark <jstark888 at gmail.com> wrote:
>>
>>  Hi,
>>
>> I installed FreeSwitch 1.2.23 on an Amazon EC2 instance (running Amazon
>> Linux). I opened port 5060 for UDP to the server. I then registered as user
>> 1005 using SipDroid on my phone via WiFi. At first when I dialed 9198, I
>> could hear the Tetris music. I could also hear the music on hold audio
>> (when I dialed 9664). However, the echo test failed. Therefore I tried
>> changing the config for the server according to this:
>> http://wiki.freeswitch.org/wiki/Amazon_EC2 However, after doing that not
>> only did the echo test not work, but neither did the Tetris or music on
>> hold tests. So I returned the config back to what it was originally.
>> Unfortunately I still can't hear the Tetris or music on hold audio. I have
>> tried using both LinPhone and XLite softphones as alternatives, but I can't
>> hear the audio on those either. Signalling appears to work. I can dial an
>> extension on a registered softphone and have another registered softphone
>> ring, but there is no audio. I would appreciate any help or insight anyone
>> has on what the problem might be. Also, I have tried using G722, PCMA, PCMU
>> and GSM audio codecs, but none have worked. All the softphones I have tried
>> are able to register without any noticeable problems.
>>
>> Thanks.
>>
>> Jeff Stark
>>
>> Below is part of the log for a typical session where I can't hear the
>> Tetris audio. (I have masked the IP addresses with descriptive labels):
>>
>>  84a7c5c8-d251-11e3-9565-7f053ccdf4d9 Dialplan: sofia/internal/1005@<FreeSwitch
>> server Public IP> Regex (PASS) [tone_stream] destination_number(9198) =~
>> /^9198$/ break=on-false
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 Dialplan: sofia/internal/1005@<FreeSwitch
>> server Public IP> Action answer()
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 Dialplan: sofia/internal/1005@<FreeSwitch
>> server Public IP> Action
>> playback({loops=10}tone_stream://path=${base_dir}/conf/tetris.ttml)
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_state_machine.c:167 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) State Change CS_ROUTING -> CS_EXECUTE
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_session.c:1351 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_state_machine.c:471 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) State ROUTING going to sleep
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_state_machine.c:415 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) Running State Change CS_EXECUTE
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_state_machine.c:478 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) State EXECUTE
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> mod_sofia.c:243 sofia/internal/1005@<FreeSwitch server Public IP> SOFIA
>> EXECUTE
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_state_machine.c:209 sofia/internal/1005@<FreeSwitch server
>> Public IP> Standard EXECUTE
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 EXECUTE sofia/internal/1005@<FreeSwitch
>> server Public IP> hash(insert/<FreeSwitch server Private
>> IP>-spymap/1005/84a7c5c8-d251-11e3-9565-7f053ccdf4d9)
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 EXECUTE sofia/internal/1005@<FreeSwitch
>> server Public IP> hash(insert/<FreeSwitch server Private
>> IP>-last_dial/1005/9198)
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 EXECUTE sofia/internal/1005@<FreeSwitch
>> server Public IP> hash(insert/<FreeSwitch server Private
>> IP>-last_dial/global/84a7c5c8-d251-11e3-9565-7f053ccdf4d9)
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 EXECUTE sofia/internal/1005@<FreeSwitch
>> server Public IP> export(RFC2822_DATE=Fri, 02 May 2014 23:28:51 +0000)
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_channel.c:1242 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 02 May 2014
>> 23:28:51 +0000]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 EXECUTE sofia/internal/1005@<FreeSwitch
>> server Public IP> answer()
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:5282 Audio Codec Compare
>> [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:3190 Set Codec sofia/internal/1005@<FreeSwitch server
>> Public IP> G722/8000 20 ms 160 samples 64000 bits
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_codec.c:111 sofia/internal/1005@<FreeSwitch server Public
>> IP> Original read codec set to G722:9
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:5451 Set 2833 dtmf send/recv payload to 101
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:3449 AUDIO RTP [sofia/internal/1005@<FreeSwitch server
>> Public IP>] <FreeSwitch server Private IP> port 23728 -> <Softphone Public
>> IP> port 50062 codec: 9 ms: 20
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:3716 Set 2833 dtmf send payload to 101
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:3722 Set 2833 dtmf receive payload to 101
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia_glue.c:3749 sofia/internal/1005@<FreeSwitch server Public IP> Set
>> rtp dtmf delay to 40
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [NOTICE]
>> sofia_glue.c:4360 Pre-Answer sofia/internal/1005@<FreeSwitch server
>> Public IP>!
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_channel.c:3368 (sofia/internal/1005@<FreeSwitch server Public
>> IP>) Callstate Change RINGING -> EARLY
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> mod_sofia.c:866 Local SDP sofia/internal/1005@<FreeSwitch server Public
>> IP>:
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 v=0
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 o=FreeSWITCH 1399049603 1399049604
>> IN IP4 <FreeSwitch server Private IP>
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 s=FreeSWITCH
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 c=IN IP4 <FreeSwitch server Private
>> IP>
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 t=0 0
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 m=audio 23728 RTP/AVP 9 101
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 a=rtpmap:9 G722/8000
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 a=rtpmap:101 telephone-event/8000
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 a=fmtp:101 0-16
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 a=ptime:20
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 a=sendrecv
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_session.c:1016 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> sofia.c:5815 Channel sofia/internal/1005@<FreeSwitch server Public IP>
>> entering state [completed][200]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_core_session.c:871 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [NOTICE]
>> mod_dptools.c:1225 Channel [sofia/internal/1005@<FreeSwitch server
>> Public IP>] has been answered
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_channel.c:3647 (sofia/internal/1005@<FreeSwitch server Public
>> IP>) Callstate Change EARLY -> ACTIVE
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 EXECUTE sofia/internal/1005@<FreeSwitch
>> server Public IP>
>> playback({loops=10}tone_stream://path=/usr/local/freeswitch/conf/tetris.ttml)
>> 2014-05-02 23:28:51.111375 [DEBUG] switch_event.c:1661 Parsing variable
>> [loops]=[10]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.111375 [DEBUG]
>> switch_ivr_play_say.c:1314 Codec Activated L16 at 16000hz 1 channels 20ms
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.331419 [DEBUG]
>> switch_core_session.c:1016 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.331419 [DEBUG]
>> switch_core_session.c:1016 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.331419 [DEBUG]
>> switch_core_session.c:1016 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:28:51.331419 [DEBUG]
>> sofia.c:5815 Channel sofia/internal/1005@<FreeSwitch server Public IP>
>> entering state [ready][200]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.331345 [DEBUG]
>> switch_core_session.c:1016 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [NOTICE]
>> sofia.c:737 Hangup sofia/internal/1005@<FreeSwitch server Public IP>
>> [CS_EXECUTE] [NORMAL_CLEARING]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_channel.c:3187 Send signal sofia/internal/1005@<FreeSwitch server
>> Public IP> [KILL]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_session.c:1351 Send signal sofia/internal/1005@<FreeSwitch
>> server Public IP> [BREAK]
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_ivr_play_say.c:1717 done playing file
>> {loops=10}tone_stream://path=/usr/local/freeswitch/conf/tetris.ttml
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_session.c:2810 sofia/internal/1005@<FreeSwitch server Public
>> IP> skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup
>> already)
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_state_machine.c:478 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) State EXECUTE going to sleep
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_state_machine.c:415 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) Running State Change CS_HANGUP
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_state_machine.c:678 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) Callstate Change ACTIVE -> HANGUP
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_state_machine.c:680 (sofia/internal/1005@<FreeSwitch server
>> Public IP>) State HANGUP
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> mod_sofia.c:506 Channel sofia/internal/1005@<FreeSwitch server Public
>> IP> hanging up, cause: NORMAL_CLEARING
>> 84a7c5c8-d251-11e3-9565-7f053ccdf4d9 2014-05-02 23:29:31.351377 [DEBUG]
>> switch_core_state_machine.c:48 sofia/internal/1005@<FreeSwitch server
>> Public IP> Standard HANGUP, cause: NORMAL_CLEARING
>>
>>
>>
>> _________________________________________________________________________
>> Professional FreeSWITCH Consulting Services:
>> consulting at freeswitch.org
>> http://www.freeswitchsolutions.com
>>
>> 
>> 
>>
>> Official FreeSWITCH Sites
>> http://www.freeswitch.org
>> http://wiki.freeswitch.org
>> http://www.cluecon.com
>>
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:consulting at freeswitch.orghttp://www.freeswitchsolutions.com
>
> FreeSWITCH-powered IP PBX: The CudaTel Communication Server
>
> Official FreeSWITCH Siteshttp://www.freeswitch.orghttp://wiki.freeswitch.orghttp://www.cluecon.com
>
> FreeSWITCH-users mailing listFreeSWITCH-users at lists.freeswitch.orghttp://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-usershttp://www.freeswitch.org
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> 
> 
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140505/f527fa72/attachment-0001.html 