Skip to content

rtpklvdepay: Recover after invalid fragmented KLV unit

The KLV depayloader can end up in a bad state if there is packet loss resulting in the last fragment of the current KLV unit being lost. This results in failure to depayload any subsequent (fragmented) units.

Illustration of the problem (each KLV unit is expected to be split up into three fragments):

fragment 0.0, start=1, marker=0
fragment 0.1, start=0, marker=0
-------------------------------  # Fragment 0.2 is lost
fragment 1.0, start=1, marker=0  # Call gst_rtp_klv_depay_process_data (start && !marker) => Not enough data in adapter (fragments 0.0, 0.1). Buffer added to adapter.
fragment 1.1, start=0, marker=0  # Add buffer to adapter.
fragment 1.2, start=0, marker=1  # Add buffer to adapter. Call gst_rtp_klv_depay_process_data (marker == TRUE) => Too much data in adapter (fragments 0.0, 0.1, 1.0, 1.1, 1.2) => Reset adapter and set resync=TRUE.
fragment 2.0, start=1, marker=0  # Call gst_rtp_klv_depay_process_data (start && !marker) => Not enough data in adapter (empty). Add buffer to adapter.
fragment 2.1, start=0, marker=0  # Dropped (resync && !start)
fragment 2.2, start=0, marker=1  # Dropped (resync && !start), set resync=FALSE (marker == TRUE)
fragment 3.0, start=1, marker=0  # Call gst_rtp_klv_depay_process_data (start && !marker) => Not enough data in adapter (fragment 2.0). Buffer added to adapter.
fragment 3.1, start=0, marker=0  # Add buffer to adapter.
fragment 3.2, start=0, marker=1  # Add buffer to adapter. Call gst_rtp_klv_depay_process_data (marker == TRUE) => Too much data in adapter (fragments 2.0, 3.0, 3.1, 3.2) => Reset adapter and set resync=TRUE.
...

Always clearing the resync flag when a start fragment is encountered avoids this issue.

Some relevant logs
0:00:42.275083000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21492, rtptime 2825005539, pts 0:00:39.907658245, dts 99:99:99.999999999
0:00:42.275084000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.275099000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21493, rtptime 2825005539, pts 0:00:39.907658245, dts 99:99:99.999999999
0:00:42.275100000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1249 bytes, marker=1, start=0
0:00:42.275102000 72370 0x6000033a8140 TRACE               klvdepay gstrtpklvdepay.c:225:gst_rtp_klv_depay_process_data:<rtpklvdepay1> 13741 bytes in adapter
0:00:42.275104000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:241:gst_rtp_klv_depay_process_data:<rtpklvdepay1> want 12353 bytes, have 13741 bytes
0:00:42.275105000 72370 0x6000033a8140 WARN                klvdepay gstrtpklvdepay.c:263:gst_rtp_klv_depay_process_data:<rtpklvdepay1> bad KLV packet, dropping
0:00:42.275107000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:130:gst_rtp_klv_depay_reset:<rtpklvdepay1> resetting
0:00:42.471112000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21494, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471120000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:327:gst_rtp_klv_depay_process:<rtpklvdepay1> Looks like the start of a fragmented KLV unit
0:00:42.471123000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=1
0:00:42.471125000 72370 0x6000033a8140 TRACE               klvdepay gstrtpklvdepay.c:225:gst_rtp_klv_depay_process_data:<rtpklvdepay1> 0 bytes in adapter
0:00:42.471149000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21495, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471151000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471152000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471168000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21496, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471169000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471171000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471185000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21497, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471187000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471188000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471202000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21498, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471204000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471205000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471218000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21499, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471219000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471220000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471234000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21500, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471235000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471236000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471250000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21501, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471252000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.471253000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.471266000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21502, rtptime 2825023539, pts 0:00:40.107658245, dts 99:99:99.999999999
0:00:42.471268000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1249 bytes, marker=1, start=0
0:00:42.471269000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:344:gst_rtp_klv_depay_process:<rtpklvdepay1> Dropping buffer, waiting to resync
0:00:42.670983000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21503, rtptime 2825041539, pts 0:00:40.307658245, dts 99:99:99.999999999
0:00:42.670991000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:327:gst_rtp_klv_depay_process:<rtpklvdepay1> Looks like the start of a fragmented KLV unit
0:00:42.670994000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=1
0:00:42.670996000 72370 0x6000033a8140 TRACE               klvdepay gstrtpklvdepay.c:225:gst_rtp_klv_depay_process_data:<rtpklvdepay1> 1388 bytes in adapter
0:00:42.671000000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:241:gst_rtp_klv_depay_process_data:<rtpklvdepay1> want 12353 bytes, have 1388 bytes
0:00:42.671002000 72370 0x6000033a8140 DEBUG               klvdepay gstrtpklvdepay.c:270:gst_rtp_klv_depay_process_data:<rtpklvdepay1> partial KLV packet: have 1388 bytes, want 12353
0:00:42.671024000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21504, rtptime 2825041539, pts 0:00:40.307658245, dts 99:99:99.999999999
0:00:42.671027000 72370 0x6000033a8140 LOG                 klvdepay gstrtpklvdepay.c:341:gst_rtp_klv_depay_process:<rtpklvdepay1> payload of 1388 bytes, marker=0, start=0
0:00:42.671049000 72370 0x6000033a8140 LOG         rtpbasedepayload gstrtpbasedepayload.c:736:gst_rtp_base_depayload_handle_buffer:<rtpklvdepay1> discont 0, seqnum 21505, rtptime 2825041539, pts 0:00:40.307658245, dts 99:99:99.999999999
Edited by Robin Gustavsson

Merge request reports