Dropped buffers with rtprtxreceive

Mon Jan 31 16:38:41 UTC 2022

Hello again,

I've managed to make progress with my issue but I still don't think 
rtprtxreceive is working right. I've also validated the same behaviour 
in the GStreamer 1.18.5 package that comes with Ubuntu 21.10. More 
details below.

On 28/01/2022 15:41, Samuel Hurst via gstreamer-devel wrote:
> Hello all,
> 
> I'm doing some investigation with the rtprtx* elements for GStreamer and 
> running into a few issues. Primarily, when I induce packet loss using 
> netem [1] on the link in order to test the retransmission functionality, 
> I get a lot of WARN-level debug output that says there's no clock-rate 
> in caps and that it's dropping buffers:
> 
> 
>> 0:00:10.753827153 197836 0x55f378160060 ERROR        rtpjitterbuffer 
>> gstrtpjitterbuffer.c:1401:gst_jitter_buffer_sink_parse_caps:<rtpjitterbuffer2> 
>> Got caps with wrong payload type (got 97, expected 96)
>> 0:00:10.753875088 197836 0x55f378160060 WARN         rtpjitterbuffer 
>> gstrtpjitterbuffer.c:3316:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer2> 
>> No clock-rate in caps!, dropping buffer
>> 0:00:10.754099058 197836 0x55f378160060 WARN               rtpsource 
>> rtpsource.c:1015:calculate_jitter: cannot get clock-rate for pt 97

<snip>

> And my receiving pipeline:
> 
>> gst-launch-1.0 -e rtpbin name=r 
>> sdes="application/x-rtp-source-sdes,cname=(string)\"samuelh\@rd.bbc.co.uk\"" 
>> udpsrc port=5000 ! 
>> "application/x-rtp,media=(string)video,clock-rate=(int)90000,encoding-name=(string)H264,payload=(int)96" 
>> ! r.recv_rtp_sink_0 r.recv_rtp_src_0_123456_96 ! rtprtxreceive 
>> payload-type-map="application/x-rtp-pt-map,96=(uint)97" ! rtpssrcdemux 
>> ! rtpjitterbuffer do-retransmission=true ! rtph264depay ! queue ! 
>> avdec_h264 ! videoconvert ! queue ! xvimagesink udpsrc port=5001 ! 
>> r.recv_rtcp_sink_0 r.send_rtcp_src_0 ! udpsink host=192.168.57.101 
>> port=6001 sync=false async=false

So today I realised that rtpbin includes an rtpjitterbuffer element, 
which explains why I was getting that message as rtpbin was before the 
rtprtxreceive element in my pipeline. I've reformulated the receiving 
pipeline so that it's now like this (without options):

udpsrc ! rtprtxreceive ! rtpssrcdemux ! rtpbin ! rtpjitterbuffer ! ...

And this has made the "No clock-rate in caps!, dropping buffer" messages 
go away. However, I'm still not convinced it's actually doing 
retransmissions properly, as I still get choppy playback.

For reference to the below, I have also added "max-size-packets=8192" to 
rtprtxsend as I was seeing the sender not having the lost packets 
available when requested occasionally.

Looking at the debug logs now, the following lines are of interest. It 
seems that the jitter buffer on the receiver side spots that a packet 
hasn't arrived in-sequence (#13935), and it sets a timer to wait for it 
to arrive (I've trimmed the log to just messages I think are relevant - 
if anyone wants the full log with rtp*:5, they are available at [1]):

> 0:00:16.885946848 48505 0x562bedce11e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:2337:update_rtx_timers:<rtpjitterbuffer0> Add RTX timer #13935, next_expected_pts 0:00:16.892798447, delay 0:00:00.020000024, est packet duration 0:00:00.040000048, jitter 0:00:00.000000006
> 0:00:16.885979722 48505 0x562bedbeca40 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3098:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer1> expected #13935, got #13936, gap of 1
> 0:00:16.885996300 48505 0x562bedbeca40 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:2461:gst_rtp_jitter_buffer_handle_missing_packets:<rtpjitterbuffer1> Missing packets: (#13935->#13935), gap 1, pts 0:00:16.852819575, last-pts 0:00:16.852819575
> 0:00:16.886016596 48505 0x562bedbeca40 INFO         rtpjitterbuffer gstrtpjitterbuffer.c:2615:gst_rtp_jitter_buffer_handle_missing_packets:<rtpjitterbuffer1> Add Lost timer for #13935, pts 0:00:16.852819575, duration 0:00:00.000000000, offset +0:00:00.200000000
> 0:00:16.886051415 48505 0x562bedce11e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3715:handle_next_buffer:<rtpjitterbuffer1> Sequence number GAP detected: expected 13935 instead of 13936 (1 missing)
> 0:00:16.886089699 48505 0x562bedce1180 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:4148:wait_next_timeout:<rtpjitterbuffer1> timer #13935 sync to timestamp 0:00:16.852819575 with sync time 6:20:02.704478418 

After ~150ms, it appears to give up on the packet arriving and then 
issues a NACK:

> 0:00:17.023860714 48505 0x562bedbec980 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3878:do_expected_timeout:<rtpjitterbuffer0> expected #13935 didn't arrive, now 0:00:16.992903378
> 0:00:17.023878235 48505 0x562bedbec980 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3906:do_expected_timeout:<rtpjitterbuffer0> Request RTX: custom-upstream event: 0x7f03d4003900, time 99:99:99.999999999, seq-num 771, GstRTPRetransmissionRequest, seqnum=(uint)13935, running-time=(guint64)16892798447, delay=(uint)100, retry=(uint)0, frequency=(uint)40, period=(uint)159, deadline=(uint)200, packet-spacing=(guint64)40000048, avg-rtt=(uint)0;
> 0:00:17.023882867 48505 0x562bedbec980 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3930:do_expected_timeout:<rtpjitterbuffer0> timer #13935 new timeout 0:00:17.032929711, rtx retry timeout 0:00:00.040000048, num_retry 1
> 0:00:17.023887233 48505 0x562bedbec980 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:4148:wait_next_timeout:<rtpjitterbuffer0> timer #13935 sync to timestamp 0:00:17.032929711 with sync time 6:20:02.884588554
> 0:00:17.023897214 48505 0x562bedbec980 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:1745:gst_rtp_jitter_buffer_src_event:<rtpjitterbuffer1> received custom-upstream
> 0:00:17.023905885 48505 0x562bedbec980 DEBUG             rtpsession rtpsession.c:4851:rtp_session_request_nack: request NACK for SSRC 0001e240, #13935, deadline 6:20:02.744611847
> 0:00:17.023910025 48505 0x562bedbec980 DEBUG              rtpsource rtpsource.c:2003:rtp_source_register_nack: append NACK #13935 with deadline 6:20:02.744611847
> 0:00:17.024010175 48505 0x562bedce08c0 DEBUG             rtpsession rtpsession.c:3601:session_start_rtcp: create RR for SSRC c515aea0
> 0:00:17.024015496 48505 0x562bedce08c0 DEBUG             rtpsession rtpsession.c:3792:session_nack: 1 NACKs current time 6:20:02.644636451
> 0:00:17.024018188 48505 0x562bedce08c0 DEBUG             rtpsession rtpsession.c:3797:session_nack: #13935 deadline 6:20:02.744611847
> 0:00:17.024021299 48505 0x562bedce08c0 DEBUG             rtpsession rtpsession.c:3878:session_nack: Sent 1 seqnums into 1 FB NACKs 

The server then responds with a retransmission packet with sequence 
number #45306 (the machines are two VMs on the same physical host, so 
minimal latency between them), but for some reason the receiver doesn't 
think that it's actually expecting #13935?!?

> 0:00:17.044164098 48505 0x562bedbeca40 DEBUG          rtprtxreceive gstrtprtxreceive.c:588:gst_rtp_rtx_receive_chain:<rtprtxreceive0> Got rtx packet: rtx seqnum 45306, rtx ssrc 3A5CC61F, rtx pt 97, orig seqnum 13935, orig pt 96
> 0:00:17.044167915 48505 0x562bedbeca40 INFO           rtprtxreceive gstrtprtxreceive.c:638:gst_rtp_rtx_receive_chain:<rtprtxreceive0> dropping rtx packet 45306 because its orig seqnum (13935) is not in our pending retransmission requests 

It then seems to loop on that packet for a bit, then eventually giving 
up and declaring it lost, even though it's had the retransmission packet 
(as verified using Wireshark):

> 0:00:17.303858296 48505 0x562bedbec980 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:2413:insert_lost_event:<rtpjitterbuffer0> Packet #13935 lost

Can someone please point out what I'm missing? Or is this a bug?

Best regards,
-Sam

[1]: 
https://www.dropbox.com/sh/ffm6zgdh3xpo0ju/AAAhtin6PIMAMb__EF-SlEyla?dl=0