rtpjitterbuffer: clean up and improve missing packets handling

* Try to make variable and function names more clear.
* Add plenty of comments describing the logic step-by-step.
* Improve the logging around this, making the logs easier to read and
  understand when debugging these issues.

* Revise the logic of packets that are actually beyond saving in doing
  the following:
1. Do an optimistic estimation of which packets can still arrive.
2. Based on this, find which packets (and duration) are now hopelessly
   lost.
3. Issue an immediate lost-event for the hopelessly lost and then add
   lost/rtx timers for the ones we still hope to save, meaning that if
   they are to arrive, they will not be discarded.

* Revise the use of rtx-delay:
  Earlier the rtx-delay would vary, depending on the pts of the latest
  packet and the estimated pts of the packet it being issued a RTX for,
  but now that we aim to estimate the PTS of the missing packet accurately,
  the RTX delay should remain the same for all packets.
  Meaning: If the packet have a PTS of X, the delay in asked for a RTX
  for this packet is always a constant X + delay, not a variable one.

* Finally ensure that the chaotic "check-for-stall" tests uses timestamps
  that starts from 0 to make them easier to debug.

Part-of: <https://gitlab.freedesktop.org/gstreamer/gst-plugins-good/-/merge_requests/952>

1 files changed, 117 insertions, 18 deletions

diff --git a/tests/check/elements/rtpjitterbuffer.c b/tests/check/elements/rtpjitterbuffer.c
index 6097ef184..af9a03a66 100644
--- a/tests/check/elements/rtpjitterbuffer.c
+++ b/tests/check/elements/rtpjitterbuffer.c
@@ -532,7 +532,9 @@ static void
 push_test_buffer_now (GstHarness * h, guint seqnum, guint32 rtptime,
     gboolean rtx)
 {
-  GstClockTime now = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element));
+  GstClockTime now =
+      gst_clock_get_time (GST_ELEMENT_CLOCK (h->element)) -
+      h->element->base_time;
   GstBuffer *buf = generate_test_buffer_full (now, seqnum, rtptime);
   if (rtx)
     GST_BUFFER_FLAG_SET (buf, GST_RTP_BUFFER_FLAG_RETRANSMISSION);
@@ -906,14 +908,18 @@ GST_START_TEST (test_late_packets_still_makes_lost_events)
           generate_test_buffer_full (now,
               seqnum, seqnum * TEST_RTP_TS_DURATION)));
 
-  /* we should now receive packet-lost-events for the gap
-   * FIXME: The timeout and duration here are a bit crap...
-   */
-  verify_lost_event (h, next_seqnum, 3400 * GST_MSECOND, 6500 * GST_MSECOND);
-  verify_lost_event (h, next_seqnum + 1,
-      9900 * GST_MSECOND, 3300 * GST_MSECOND);
+  /* We get one "huge" lost-event accounting for all the missing time */
+  verify_lost_event (h, next_seqnum, 120 * GST_MSECOND, 9860 * GST_MSECOND);
+
+  /* and the next packet is optimistically expected to be the one
+     just prior to our current packet, so we time that out with a crank */
+  gst_harness_crank_single_clock_wait (h);
 
-  /* verify that packet @seqnum made it through! */
+  /* and we verify that indeed this lost event was thought to should
+     have arrived 20ms prior to the packet that actually arrived */
+  verify_lost_event (h, next_seqnum + 1, 9980 * GST_MSECOND, 20 * GST_MSECOND);
+
+  /* and finally verify that the super-late packet made it through! */
   out_buf = gst_harness_pull (h);
   fail_unless (GST_BUFFER_FLAG_IS_SET (out_buf, GST_BUFFER_FLAG_DISCONT));
   fail_unless_equals_int (seqnum, get_rtp_seq_num (out_buf));
@@ -1248,12 +1254,101 @@ GST_START_TEST (test_loss_equidistant_spacing_with_parameter_packets)
   gst_harness_push (h, generate_test_buffer_full (frame * TEST_BUF_DURATION,
           seq + 1, frame * TEST_RTP_TS_DURATION));
 
-  /* Check that the lost event has been generated assuming equidistant
-   * spacing. */
-  verify_lost_event (h, seq,
-      frame * TEST_BUF_DURATION - TEST_BUF_DURATION / 2, TEST_BUF_DURATION / 2);
+  /* given that the last known PTS (pkt#12) was 200ms and this last PTS (pkt#14) was 220ms,
+     and our current packet-spacing is 20ms, the lost-event gets a problem here:
+     If we use our packet-spacing, the last pushed packet (#12) should have
+     a duration of 20ms, meaning we would expect the missing packet (#13) to
+     have a PTS of 220ms. However, packet #14 comes in at 220ms, so what is
+     the best estimation for the missing packet here?
+
+     Given that we want to estimate the most optimistic PTS in order to give
+     the packet as many chances as possible to arrive, we end up with a PTS
+     of 220ms and a duration of 0, since that will be the most optimistic
+     placement given that it has to be before pkt #14.
+   */
+
+  /* timeout the lost-event */
+  gst_harness_crank_single_clock_wait (h);
+  verify_lost_event (h, seq, frame * TEST_BUF_DURATION, 0);
+
+  gst_buffer_unref (gst_harness_pull (h));
+
+  gst_harness_teardown (h);
+}
+
+GST_END_TEST;
+
+
+typedef struct
+{
+  guint gap;
+  GstClockTime duration[3];
+} ThreeLostPackets;
+
+ThreeLostPackets no_fractional_lost_event_durations_input[] = {
+  {5, {60 * GST_MSECOND, 20 * GST_MSECOND, 20 * GST_MSECOND}},
+  {4, {40 * GST_MSECOND, 20 * GST_MSECOND, 20 * GST_MSECOND}},
+  {3, {20 * GST_MSECOND, 20 * GST_MSECOND, 20 * GST_MSECOND}},
+  {2, {20 * GST_MSECOND, 20 * GST_MSECOND, 0 * GST_MSECOND}},
+  {1, {20 * GST_MSECOND, 0 * GST_MSECOND, 0 * GST_MSECOND}},
+  {0, {0 * GST_MSECOND, 0 * GST_MSECOND, 0 * GST_MSECOND}},
+};
+
+/* This test looks after that fact that when we have equidistant
+   packetspacing, we try and keep that spacing for the lost events,
+   so we operate in "whole" packets.
+*/
+GST_START_TEST (test_no_fractional_lost_event_durations)
+{
+  ThreeLostPackets *ctx = &no_fractional_lost_event_durations_input[__i__];
+
+  GstHarness *h = gst_harness_new ("rtpjitterbuffer");
+  GstClockTime now;
+  guint latency_ms = 100;
+  guint16 seqnum, gap_seqnum;
+  GstClockTime pts;
+  GstClockTime duration;
+
+  g_object_set (h->element, "do-lost", TRUE, NULL);
+  seqnum = construct_deterministic_initial_state (h, latency_ms);
+  gap_seqnum = seqnum + ctx->gap;
+
+  now = gap_seqnum * TEST_BUF_DURATION;
+  gst_harness_set_time (h, now);
+  fail_unless_equals_int (GST_FLOW_OK, gst_harness_push (h,
+          generate_test_buffer_full (now,
+              seqnum + 3, gap_seqnum * TEST_RTP_TS_DURATION)));
+
+  pts = seqnum * TEST_BUF_DURATION;
+  now = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element));
+  /* check if the lost-event has expired, if not
+     crank to move the time ahead */
+  if (pts + latency_ms * GST_MSECOND > now)
+    gst_harness_crank_single_clock_wait (h);
+  duration = ctx->duration[0];
+  verify_lost_event (h, seqnum, pts, duration);
+
+  seqnum++;
+  pts += duration;
+  duration = ctx->duration[1];
+  now = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element));
+  if (pts + latency_ms * GST_MSECOND > now)
+    gst_harness_crank_single_clock_wait (h);
+  verify_lost_event (h, seqnum, pts, duration);
+
+  seqnum++;
+  pts += duration;
+  duration = ctx->duration[2];
+  now = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element));
+  if (pts + latency_ms * GST_MSECOND > now)
+    gst_harness_crank_single_clock_wait (h);
+  verify_lost_event (h, seqnum, pts, duration);
 
+  /* followed by the buffer */
   gst_buffer_unref (gst_harness_pull (h));
+  /* verify that we have pulled out all waiting buffers and events */
+  fail_unless_equals_int (0, gst_harness_buffers_in_queue (h));
+  fail_unless_equals_int (0, gst_harness_events_in_queue (h));
 
   gst_harness_teardown (h);
 }
@@ -1706,8 +1801,7 @@ GST_START_TEST (test_rtx_duplicate_packet_updates_rtx_stats)
   gint latency_ms = 100;
   gint next_seqnum;
   GstClockTime now, rtx_request_6, rtx_request_7;
-  gint rtx_delay_ms_0 = TEST_BUF_MS / 2;
-  gint rtx_delay_ms_1 = TEST_BUF_MS;
+  gint rtx_delay_ms = TEST_BUF_MS / 2;
   gint i;
 
   g_object_set (h->element, "do-retransmission", TRUE, NULL);
@@ -1721,17 +1815,17 @@ GST_START_TEST (test_rtx_duplicate_packet_updates_rtx_stats)
   /* Wait for NACKs on 6 and 7 */
   gst_harness_crank_single_clock_wait (h);
   verify_rtx_event (h, 6, 6 * TEST_BUF_DURATION,
-      rtx_delay_ms_0, TEST_BUF_DURATION);
+      rtx_delay_ms, TEST_BUF_DURATION);
   rtx_request_6 = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element));
   fail_unless_equals_int64 (rtx_request_6,
-      6 * TEST_BUF_DURATION + rtx_delay_ms_0 * GST_MSECOND);
+      6 * TEST_BUF_DURATION + rtx_delay_ms * GST_MSECOND);
 
   gst_harness_crank_single_clock_wait (h);
   verify_rtx_event (h,
-      7, 7 * TEST_BUF_DURATION, rtx_delay_ms_1, TEST_BUF_DURATION);
+      7, 7 * TEST_BUF_DURATION, rtx_delay_ms, TEST_BUF_DURATION);
   rtx_request_7 = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element));
   fail_unless_equals_int64 (rtx_request_7,
-      7 * TEST_BUF_DURATION + rtx_delay_ms_1 * GST_MSECOND);
+      7 * TEST_BUF_DURATION + rtx_delay_ms * GST_MSECOND);
 
   /* Original packet 7 arrives */
   now = 161 * GST_MSECOND;
@@ -3093,6 +3187,8 @@ check_for_stall (GstHarness * h, BufferArrayCtx * bufs, guint num_bufs)
   GArray *array;
 
   gst_harness_use_systemclock (h);
+  gst_element_set_base_time (h->element,
+      gst_clock_get_time (GST_ELEMENT_CLOCK (h->element)));
   gst_harness_set_src_caps (h, generate_caps ());
 
   g_object_get (h->element, "latency", &latency_ms, NULL);
@@ -3218,6 +3314,9 @@ rtpjitterbuffer_suite (void)
   tcase_add_test (tc_chain, test_reorder_of_non_equidistant_packets);
   tcase_add_test (tc_chain,
       test_loss_equidistant_spacing_with_parameter_packets);
+  tcase_add_loop_test (tc_chain, test_no_fractional_lost_event_durations, 0,
+      G_N_ELEMENTS (no_fractional_lost_event_durations_input));
+
 
   tcase_add_test (tc_chain, test_rtx_expected_next);
   tcase_add_test (tc_chain, test_rtx_not_bursting_requests);