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

Fri Nov 20 17:20:06 UTC 2020

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> wrote:

Any response to this?

On Nov 7, 2020, at 9:26 PM, David Horton <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 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 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 [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 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 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 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> 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> wrote:
No, they are audio only.

On Nov 4, 2020, at 10:22 AM, Dragos Oancea <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> wrote:
Good point - but I have not enabled jitter buffer.

On Nov 4, 2020, at 10:08 AM, Dragos Oancea <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> 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
_________________________________________________________________________