[Freeswitch-dev] FreeSWITCH erroneous RTP timestamps in front of sofsip_cli client?

[Jean-Paul Iribarren]

Hi FS wizards, first message on this list... Apologies if this post
belongs to another section (please tell me if this is the case).

First, a big thank you to all members of the team for this amazing piece
of software. Great job here. Now, on for my issue: I am currently
testing a Linux sofsip_cli SIP client on an embedded device, connected
to a Win32 FreeSWITCH version, and I can't get correct RX audio on my
platform. I ran the same test with a linphonec client on the same
embedded device for comparison purposes, and the rx audio is good. Both
clients end up using the same RTP configuration (PCMU/8000). Preliminary
conclusion: my sofsip_cli client is buggy. But there is more...

I ended up checking data exchanged between endpoints using Wireshark,
and I was surprised to see that in front of sofsip_cli, FreeSWITCH seems
to timestamp TX RTP packets incorrectly: it sends 160 samples/RTP
packet, but the timestamps of consecutive TX packets are increased in
320 units steps, and FS sends 25 RTP packets per second on average.
Consecutive RTP packets actually contain consecutive PCMU data (from the
audio point of view), resulting in a sloooow, chopped rx audio coming
out of the loudspeaker of my device. Using Wireshark embedded player to
play the VoIP audio results in the same slow / chopped audio, which
seems to prove that FS actually sent bad RTP.

On the other hand, when I use linphonec in the very same conditions, I
can see that FreeSWITCH sends 50 RTP packets per second on average. Each
RTP packet contains 160 samples, and timestamps of consecutive are
increased in 160 units steps, resulting in correct RX audio coming out
of the loudspeaker of my device. FS logs in console window are the same
for both cases, below is what I get for the sofsip_cli case:

2013-11-21 09:35:00.549253 [NOTICE] switch_channel.c:1055 New Channel
sofia/internal/1009 at 10.0.0.57 [527f855e-3856-4805-b72c-da59b3a6d292]
2013-11-21 09:35:04.502530 [INFO] mod_dialplan_xml.c:558 Processing 1009
<1009>->1001 in context default
2013-11-21 09:35:04.533781 [INFO] switch_ivr_async.c:3631 Bound B-Leg:
*1 execute_extension::dx XML features
2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg:
*2 record_session::C:/Program
Files/FreeSWITCH/recordings/1009.2013-11-21-09-35-04.wav
2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg:
*3 execute_extension::cf XML features
2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg:
*4 execute_extension::att_xfer XML features
2013-11-21 09:35:04.565032 [NOTICE] switch_ivr_originate.c:2699 Cannot
create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2013-11-21 09:35:04.565032 [NOTICE] switch_ivr_originate.c:2699 Cannot
create outgoing channel of type [user] cause: [USER_NOT_REGISTERED]
2013-11-21 09:35:04.580658 [INFO] mod_dptools.c:3201 Originate Failed. 
Cause: USER_NOT_REGISTERED
2013-11-21 09:35:04.580658 [NOTICE] sofia_media.c:92 Pre-Answer
sofia/internal/1009 at 10.0.0.57!
2013-11-21 09:35:04.580658 [NOTICE] mod_dptools.c:1225 Channel
[sofia/internal/1009 at 10.0.0.57] has been answered
2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1055 New Channel
loopback/app=voicemail:default 10.0.0.57 1001-a
[f2aa95f1-0631-4590-9fa4-c4dc1c96c88e]
2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1053 Rename Channel
loopback/app=voicemail:default 10.0.0.57 1001-a->loopback/voicemail-a
[f2aa95f1-0631-4590-9fa4-c4dc1c96c88e]
2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1055 New Channel
loopback/voicemail-b [fc478cfd-e932-450a-9f50-2a5a76acc907]
2013-11-21 09:35:05.611948 [NOTICE] mod_loopback.c:947 Pre-Answer
loopback/voicemail-a!
2013-11-21 09:35:05.611948 [NOTICE] mod_dptools.c:1260 Pre-Answer
loopback/voicemail-b!
2013-11-21 09:35:11.549676 [NOTICE] sofia.c:715 Hangup
sofia/internal/1009 at 10.0.0.57 [CS_EXECUTE] [NORMAL_CLEARING]
2013-11-21 09:35:11.565301 [NOTICE] switch_ivr_bridge.c:733 Hangup
loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
2013-11-21 09:35:11.565301 [NOTICE] mod_loopback.c:553 Hangup
loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL]
2013-11-21 09:35:11.580927 [NOTICE] switch_core_session.c:1598 Session 5
(loopback/voicemail-a) Ended
2013-11-21 09:35:11.580927 [NOTICE] switch_core_session.c:1602 Close
Channel loopback/voicemail-a [CS_DESTROY]
2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1598 Session 4
(sofia/internal/1009 at 10.0.0.57) Ended
2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1602 Close
Channel sofia/internal/1009 at 10.0.0.57 [CS_DESTROY]
2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1598 Session 6
(loopback/voicemail-b) Ended
2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1602 Close
Channel loopback/voicemail-b [CS_DESTROY]

I ran my tests by calling an unregistered extension (1001), therefore
resulting in FS sending voice messaging audio, and hanging up on client
after a few seconds. I have compared the SIP handshakes for both
clients, and I can't see any significant difference (except that
linphonec supports several codecs, while sofsip_cli only supports
G.711/PCMU).

Regarding FS config (this may or may not be relevant), I had to tweak it
a bit to support sofsip_cli. I added the two following lines in the
dialplan for the relevant extensions (file default.xml):

     <action application="set" data="disable_rtp_auto_adjust=true"/>
     <action application="set" data="zrtp_secure_media=false"/>

I also changed the two following lines to add video codecs in file vars.xml:

   <X-PRE-PROCESS cmd="set"
data="global_codec_prefs=G722,PCMU,PCMA,GSM,H263,H263-1998,H264"/>
   <X-PRE-PROCESS cmd="set"
data="outbound_codec_prefs=PCMU,PCMA,GSM,H263,H263-1998,H264"/>

The rest of the config is plain vanilla.

The (small) Wireshark traces of both tests can be downloaded from
Box:

- linphonec trace (FS TX RTP ok): file linphone.dac.pcap is available at
https://app.box.com/s/63p8ayrr3dc6w1d9wm33

- sofsip_cli trace (FS TX RTP ko): file ssc.pcap is available at
https://app.box.com/s/z1cde37xg5teh9d690oy

My device has IP address 10.0.0.186, and FS is installed on my PC
(running Win XP Pro) at 10.0.0.57.

My FreeSWITCH version is "1.5.6b+git~20131101T202135Z~2589bf7750~32bit
(git 2589bf7 2013-11-01 20:21:35Z 32bit)"

Sorry for the long post (I tried to give all relevant info), and thank
you in advance for your comments and help on this weird issue.
-- 
JPI