[Freeswitch-users] Freeswitch (incorrectly?) reporting packet loss via RTCP

Fri Nov 20 20:39:25 UTC 2020

Thanks for the insight on this — exactly what I wanted to know.  In my deployments I’ve seen two side affects to this:

1) lower quality results from “brittle” downstream voice analysis systems that don’t do well with missing packets (e.g some speaker verification systems that I’ve integrated with) 
2) consistent reports of poor QoS on calls to freeswitch which can lead to a lot of time/effort trying to troubleshoot things on the network etc when that isnt really the cause.

Now that I know the background on this I can consider the best path for me to take in my applications; e.g. fork/patch or accept/ignore.

Thanks again, 

Dave
On Nov 20, 2020, at 2:53 PM, Christopher Rienzo <cmrienzo at gmail.com> wrote:

Hi Dave,

I appreciate the time you and many in our community spend understanding how freeswitch works when reporting issues.

For audio, RTP is usually handled by the same thread that is executing dialplan apps.  Dialplan apps must not spend a lot of time on blocking operations otherwise RTP will not be processed in time.  switch_ivr_play_file() is one of many core functions dialplan apps execute and it is responsible for reading and writing audio frames.  Knowing that FS can fall behind, it is a common pattern in FS to flush buffers prior to playing.  In 1-legged calls this should have no bad effect, however you've noticed a side-effect of that in the RTCP reports.

Chris

On Fri, Nov 20, 2020 at 12:57 PM David Horton <daveh at drachtio.org <mailto:daveh at drachtio.org>> wrote:
Could someone on the freeswitch team please respond to this?  I spent a fair bit of time/effort gathering logs and investigating, and would like a quick answer to the question “why does freeswitch discard incoming RTP packets when starting to pay a file?”

Dave

On Nov 11, 2020, at 3:44 PM, David Horton <daveh at drachtio.org <mailto:daveh at drachtio.org>> wrote:

Any response to this?

On Nov 7, 2020, at 9:26 PM, David Horton <daveh at drachtio.org <mailto:daveh at drachtio.org>> wrote:

I have investigated this further, and for some reason the issue seems to be related to the fact that I am playing a file on the channel, and when the file starts playing freeswitch for some reason flushes packets, which then occasionally leads to freeswitch reporting lost packets (the very packets it flushed).

I’m lacking some information to fully understand this — most importantly, I would like to know what the function of doing an AUDIO_SYNC on the channel when a file finishes playing, and why this should cause freeswitch to flush incoming packets?

Here, step by step, is what I observe:

1.  I issue a command to play an mp3 file on the channel
2.  When the file starts playing, I see freeswitch issue an AUDIO_SYNC event
3. This causes freeswitch to set the SWITCH_RTP_FLAG_FLUSH flag on the channel
4.  Freeswitch then does a non-blocking read on the UDP socket and discards any packets it receives — this is where incoming packets get dropped on the floor — not all the times, only if the non-blocking read happens just as a packet was received at the network layer
5.  Once the non-blocking read fails, freeswitch turns off the SWITCH_RTP_FLAG_FLUSH flag and continues on.

Therefore, every time a play file command starts, there appears to be a chance of dropping some packets.

Below is some logging showing the above sequence of events (I’ve added some additional logging).

So, for the freeswitch team — can you provide some background info on why we would want to discard *incoming* packets when we start streaming an *outbound* audio file?

What exactly are we trying to solve for here?

Am I doing something wrong somehow? 

********
EXECUTE [depth=1] sofia/drachtio_mrf/nobody at 172.31.32.120:5060 <http://nobody@172.31.32.120:5060/> playback(/tmp/tts-02413eaa-538f-49cc-be9f-54f71e45f389e572411e7d5b2eda396848cd8c4ff467c47513a9.mp3)
2020-11-08 02:14:49.087939 [ALERT] switch_core_session.c:2889 sofia/drachtio_mrf/nobody at 172.31.32.120:5060 <http://nobody@172.31.32.120:5060/> receive message [APPLICATION_EXEC]
2020-11-08 02:14:49.087939 [ALERT] switch_core_session.c:1047 Send signal sofia/drachtio_mrf/nobody at 172.31.32.120:5060 <http://nobody@172.31.32.120:5060/> [BREAK]
2020-11-08 02:14:49.087939 [DEBUG] switch_ivr_play_say.c:1492 Codec Activated L16 at 8000hz 1 channels 20ms
2020-11-08 02:14:49.087939 [ALERT] switch_ivr_play_say.c:1423 sofia/drachtio_mrf/nobody at 172.31.32.120:5060 <http://nobody@172.31.32.120:5060/> receive message [AUDIO_SYNC]
2020-11-08 02:14:49.087939 [DEBUG] switch_rtp.c:7627 starting to flush packets
2020-11-08 02:14:49.087939 [ERR] switch_rtp.c:5704 *** do_flush: total flushed packets: 2 ***
2020-11-08 02:14:49.087939 [DEBUG] switch_rtp.c:7631 done flushing packets
2020-11-08 02:14:49.087939 [ALERT] switch_core_media.c:15808 sofia/drachtio_mrf/nobody at 172.31.32.120:5060 <http://nobody@172.31.32.120:5060/> receive message [TRANSCODING_NECESSARY]
2020-11-08 02:14:49.107937 [ERR] switch_rtp.c:6123 Missed 2 RTP frames from sequence [11395] to [11396] (flushed by FS). Time since last read [19998]
2020-11-08 02:14:49.307936 [ALERT] switch_rtp.c:1572 sofia/drachtio_mrf/nobody at 172.31.32.120:5060 <http://nobody@172.31.32.120:5060/> audio 2 consecutive flaws, adding 2 flaw penalty
2020-11-08 02:14:49.727937 [ALERT] switch_rtp.c:1846 LOST PACKETS!! expected 53, got 51, highest: 11427, last_rpt_ext_seq 11374, extra 0
2020-11-08 02:14:49.727937 [CRIT] switch_rtp.c:1867 rtcp_generate_sr: stats_ssrc[288672665] received[51] expected[53] cum[3] lost[2|9/256]pkt last_seq[11427] cyc[0] last_rpt_seq[11374] cyc[0] ssrc[288672665]
*********

On Nov 5, 2020, at 11:12 AM, Dragos Oancea <dragos at freeswitch.org <mailto:dragos at freeswitch.org>> wrote:

Chris pointed out that the packets need to be there, at the app level, when FS wants them, even if the JB is not used. And how are you sure that those packets are not actually lost for FS ? What network stats ? Also, OS/network interfaces have very large buffers.  

On Wed, Nov 4, 2020 at 5:29 PM David Horton <daveh at drachtio.org <mailto:daveh at drachtio.org>> wrote:
No, they are audio only.

On Nov 4, 2020, at 10:22 AM, Dragos Oancea <dragos at freeswitch.org <mailto:dragos at freeswitch.org>> wrote:

Are these video calls ? JB gets enabled by default for video.

On Wed, Nov 4, 2020 at 5:12 PM David Horton <daveh at drachtio.org <mailto:daveh at drachtio.org>> wrote:
Good point - but I have not enabled jitter buffer.

On Nov 4, 2020, at 10:08 AM, Dragos Oancea <dragos at freeswitch.org <mailto:dragos at freeswitch.org>> wrote:

What's in the RTCP report is what comes after passing through the Jitter Buffer, if there's jitter , some packets are late and they will be dropped by JB.

On Tue, Nov 3, 2020 at 7:26 PM David Horton <daveh at drachtio.org <mailto:daveh at drachtio.org>> wrote:
I have a freeswitch server v1.10.1 running on AWS EC2 which I have noticed is reporting lost packets in the RTCP reports it is sending out.  This happens even with a single call.  Meanwhile, the network stats on the same instances show no dropped packets and no packet receive errors.  Is there anything which could explain this?  Have others seen errors in the RTCP stats reported by freeswitch?

dave
_________________________________________________________________________