tests: jibuf_test: Add scenario to show out-of-order bug

Related: OS#3262

Change-Id: I1e78cc44f8a04dcb983352b513f8de2574b2394b

2 files changed, 83 insertions, 0 deletions

diff --git a/tests/jibuf/jibuf_test.c b/tests/jibuf/jibuf_test.c
index c0c24fd..7993a65 100644
--- a/tests/jibuf/jibuf_test.c
+++ b/tests/jibuf/jibuf_test.c
@@ -619,6 +619,66 @@ static void test_rtp_marker(void)
 	osmo_jibuf_delete(jb);
 }
 
+/* This test aims at testing scenarios described in OS#3262, in which syncpoint
+   packets can provoke a situation in which packets are stored out-of-order in
+   the queue. */
+static void test_rtp_marker_queue_order()
+{
+	int min_delay = 60;
+	struct msgb *msg;
+	struct rtp_hdr *rtph;
+
+	printf("===test_rtp_marker_queue_order===\n");
+
+	clock_override_enable(true);
+	clock_override_set(0, 0);
+	rtp_init(32, 400);
+	jb = osmo_jibuf_alloc(NULL);
+	osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL);
+	osmo_jibuf_set_min_delay(jb, min_delay);
+	osmo_jibuf_set_max_delay(jb, 200);
+
+	/* First rtp at t=0, should be scheduled in min_delay time */
+	clock_debug("enqueue 1st packet");
+	ENQUEUE_NEXT(jb);
+	clock_override_add(0, TIME_RTP_PKT_MS*1000);
+	clock_debug("enqueue 2nd packet");
+	ENQUEUE_NEXT(jb);
+	clock_override_add(0, TIME_RTP_PKT_MS*1000);
+	clock_debug("enqueue 3rd packet");
+	ENQUEUE_NEXT(jb);
+	clock_override_add(0, TIME_RTP_PKT_MS*1000);
+
+	/* We then emulate an scenario in which an Osmux queue in front of us
+	   receives a new frame before expected time, which means the packets in
+	   the osmux genreated rtp queue will be flushed and sent to jibuf
+	   directly. On top, the first packet of the new frame has the RTP
+	   Marker bit set. */
+	clock_debug("enqueue 3 packets instantly");
+	ENQUEUE_NEXT(jb); /* scheduled min_delay+0 */
+	ENQUEUE_NEXT(jb); /* a min_delay+TIME_RTP_PKT_MS */
+	ENQUEUE_NEXT(jb); /* scheduled min_delay+TIME_RTP_PKT_MS*2 */
+	clock_debug("enqueue pkt with marker=1 instantly");
+	msg = rtp_next();
+	rtph = osmo_rtp_get_hdr(msg);
+	rtph->marker = 1;
+	OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg) == 0); /* syncpoint, scheduled in min_delay+0 */
+	osmo_select_main(0);
+
+	clock_override_add(0, TIME_RTP_PKT_MS*1000);
+	clock_debug("enqueue pkt after syncpoint");
+	ENQUEUE_NEXT(jb); /* scheduled min_delay+0 */
+
+	clock_debug("all packets dequeued");
+	clock_override_add(0, min_delay*1000);
+	osmo_select_main(0);
+
+	/* This assert shows that packets are queued out of order in this case:*/
+	OSMO_ASSERT(!osmo_jibuf_empty(jb));
+
+	osmo_jibuf_delete(jb);
+}
+
 static void test_rtp_out_of_sync(unsigned int time_inc_ms, uint16_t seq_nosync_inc, uint32_t ts_nosync_inc, bool expect_drop)
 {
 	int min_delay = 60;
@@ -754,6 +814,7 @@ int main(int argc, char **argv)
 	test_seq_wraparound();
 	test_timestamp_wraparound();
 	test_rtp_marker();
+	test_rtp_marker_queue_order();
 	test_rtp_out_of_sync(80*TIME_RTP_PKT_MS, 5, 5*SAMPLES_PER_PKT, true);
 	test_rtp_out_of_sync(80*TIME_RTP_PKT_MS, 6, 5*SAMPLES_PER_PKT, false);
 	test_rtp_out_of_sync(80*TIME_RTP_PKT_MS, 5, 5*SAMPLES_PER_PKT + 3, false);
diff --git a/tests/jibuf/jibuf_test.ok b/tests/jibuf/jibuf_test.ok
index e495435..6bf52fb 100644
--- a/tests/jibuf/jibuf_test.ok
+++ b/tests/jibuf/jibuf_test.ok
@@ -365,6 +365,28 @@ sys={0.140000}, mono={0.140000}: 2 packets dequeued
 sys={0.200000}, mono={0.200000}: clock_override_add
 sys={0.200000}, mono={0.200000}: dequeue: seq=35 ts=880 INTERMEDIATE
 sys={0.200000}, mono={0.200000}: dequeue: seq=36 ts=1040 LATEST
+===test_rtp_marker_queue_order===
+sys={0.000000}, mono={0.000000}: clock_override_set
+sys={0.000000}, mono={0.000000}: enqueue 1st packet
+sys={0.020000}, mono={0.020000}: clock_override_add
+sys={0.020000}, mono={0.020000}: enqueue 2nd packet
+sys={0.040000}, mono={0.040000}: clock_override_add
+sys={0.040000}, mono={0.040000}: enqueue 3rd packet
+sys={0.060000}, mono={0.060000}: clock_override_add
+sys={0.060000}, mono={0.060000}: enqueue 3 packets instantly
+sys={0.060000}, mono={0.060000}: enqueue pkt with marker=1 instantly
+sys={0.060000}, mono={0.060000}: dequeue: seq=33 ts=560 INTERMEDIATE
+sys={0.080000}, mono={0.080000}: clock_override_add
+sys={0.080000}, mono={0.080000}: enqueue pkt after syncpoint
+sys={0.080000}, mono={0.080000}: all packets dequeued
+sys={0.140000}, mono={0.140000}: clock_override_add
+sys={0.140000}, mono={0.140000}: dequeue: seq=34 ts=720 INTERMEDIATE
+sys={0.140000}, mono={0.140000}: dequeue: seq=35 ts=880 INTERMEDIATE
+sys={0.140000}, mono={0.140000}: dequeue: seq=36 ts=1040 INTERMEDIATE
+sys={0.140000}, mono={0.140000}: dequeue: seq=39 ts=1520 INTERMEDIATE
+sys={0.140000}, mono={0.140000}: dequeue: seq=37 ts=1200 INTERMEDIATE
+sys={0.140000}, mono={0.140000}: dequeue: seq=40 ts=1680 LATEST
+sys={0.140000}, mono={0.140000}: dequeue: seq=38 ts=1360 INTERMEDIATE
 ===test_rtp_out_of_sync(1600, 5, 800, 1)===
 sys={0.000000}, mono={0.000000}: clock_override_set
 sys={0.000000}, mono={0.000000}: enqueue 1st packet (seq=33, ts=560)