Corrupted frames when decoding H264 (high profile) from RTP

Sat Jan 26 21:38:03 UTC 2019

Safari 12 now encodes WebRTC video using the H264 high profile which is causing the frames in my pipeline to get corrupted (it works fine with videos from Safari 11 which uses the baseline profile).

Here is my Gstreamer pipeline:

gst-launch-1.0 -v udpsrc port=55002 ! application/x-rtp,clock-rate=90000,payload=96 ! rtpjitterbuffer mode=0 ! rtph264depay ! h264parse ! avdec_h264 ! videoconvert ! pngenc ! multifilesink location=frame%03d.png 

However, if I use FFmpeg like this, the frames get saved fine:

ffmpeg -r 30 -an -protocol_whitelist file,udp,rtp -i video.sdp frame%3d.png

Here is the SDP:

v=0
o=- 0 0 IN IP4 127.0.0.1
s=iProov HTML5 Client
c=IN IP4 127.0.0.1
t=0 0
m=video 55002 RTP/AVP 96
a=rtpmap:96 H264/90000
a=fmtp:96 packetization-mode=1

I have saved a copy of the RTP stream using rtpdump:

https://www.cs.columbia.edu/irt/software/rtptools/

This allows the stream to be replayed with rtpplay:

rtpplay -v -T -f video.rtp localhost/55002

And here is the rtp dump file I am using:

https://drive.google.com/file/d/1j3yrYP00RxHTWobD450Ar3fzO8ZIQuas/view?usp=sharing

Restreaming this file in this way to FFmpeg works great but to Gstreamer produces corrupted frames with the above commands. 

If I turn up the RTP log level, I see many "illegal short term buffer state detected" errors like this:

0:00:07.425906669 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3055:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> expected #70, got #70, gap of 0
0:00:07.425939062 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3084:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> Clearing gap packets
0:00:07.425968309 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3230:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> Pushed packet #70, now 10 packets, head: 0, percent -1
0:00:07.430274718 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:2957:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> Received packet #71 at time 0:00:07.370746462, discont 0, rtx 0
0:00:07.430316978 31333      0x27669e0 LOG          rtpjitterbuffer gstrtpjitterbuffer.c:2662:calculate_jitter:<rtpjitterbuffer0> dtsdiff 0:00:00.004545914 rtptime 0:00:00.054000000, clock-rate 90000, diff 0:00:00.049454086, jitter: 0:00:00.050701297
0:00:07.430336648 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3055:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> expected #71, got #71, gap of 0
0:00:07.430347687 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3084:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> Clearing gap packets
0:00:07.430368877 31333      0x27669e0 DEBUG        rtpjitterbuffer rtpjitterbuffer.c:785:rtp_jitter_buffer_calculate_pts: extrtp 306540, gstrtp 0:00:03.406000000, base 0:00:02.651000000, send_diff 0:00:00.755000000
0:00:07.430388707 31333      0x27669e0 DEBUG        rtpjitterbuffer rtpjitterbuffer.c:563:calculate_skew: time 0:00:07.370746462, base 0:00:07.248430817, recv_diff 0:00:00.122315645, slope 49
0:00:07.430401151 31333      0x27669e0 DEBUG        rtpjitterbuffer rtpjitterbuffer.c:580:calculate_skew: filling 2, delta -632684355
0:00:07.430415334 31333      0x27669e0 DEBUG        rtpjitterbuffer rtpjitterbuffer.c:664:calculate_skew: skew -195415049, out 0:00:07.808015768
0:00:07.430424474 31333      0x27669e0 DEBUG        rtpjitterbuffer rtpjitterbuffer.c:916:rtp_jitter_buffer_calculate_pts: backwards timestamps, using previous time
0:00:07.430451918 31333      0x27669e0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3230:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> Pushed packet #71, now 11 packets, head: 0, percent -1
0:00:07.464803911 31333      0x26d80a0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3517:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 61, dts 0:00:07.248430817, pts 0:00:07.248430817
0:00:07.464827595 31333      0x26d80a0 LOG         rtpbasedepayload gstrtpbasedepayload.c:359:gst_rtp_base_depayload_handle_buffer:<rtph264depay0> discont 0, seqnum 61, rtptime 238590, pts 0:00:07.248430817, dts 0:00:07.248430817
0:00:07.464837300 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:1026:gst_rtp_h264_depay_process:<rtph264depay0> receiving 811 bytes
0:00:07.464843846 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:1046:gst_rtp_h264_depay_process:<rtph264depay0> NRI 1, Type 24
0:00:07.464853441 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal:<rtph264depay0> handle NAL type 1
0:00:07.464859635 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:904:gst_rtp_h264_depay_handle_nal:<rtph264depay0> start 1, complete 1
0:00:07.464864758 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal:<rtph264depay0> adding NAL to picture adapter
0:00:07.464873130 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal:<rtph264depay0> handle NAL type 1
0:00:07.464878908 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:904:gst_rtp_h264_depay_handle_nal:<rtph264depay0> start 1, complete 0
0:00:07.464884010 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal:<rtph264depay0> adding NAL to picture adapter
0:00:07.464895585 31333      0x26d80a0 DEBUG        rtpjitterbuffer gstrtpjitterbuffer.c:3517:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 62, dts 0:00:07.248753067, pts 0:00:07.248430817
0:00:07.464906056 31333      0x26d80a0 LOG         rtpbasedepayload gstrtpbasedepayload.c:359:gst_rtp_base_depayload_handle_buffer:<rtph264depay0> discont 0, seqnum 62, rtptime 238590, pts 0:00:07.248430817, dts 0:00:07.248753067
0:00:07.464912715 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:1026:gst_rtp_h264_depay_process:<rtph264depay0> receiving 1058 bytes
0:00:07.464918633 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:1046:gst_rtp_h264_depay_process:<rtph264depay0> NRI 1, Type 24
0:00:07.464925747 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal:<rtph264depay0> handle NAL type 1
0:00:07.464930885 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal:<rtph264depay0> adding NAL to picture adapter
0:00:07.464936129 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:778:gst_rtp_h264_complete_au:<rtph264depay0> taking completed AU
0:00:07.464941830 31333      0x26d80a0 LOG             rtph264depay gstrtph264depay.c:756:gst_rtp_h264_depay_allocate_output_buffer:<rtph264depay0> want output buffer of 1458 bytes
0:00:07.466015023 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal:<rtph264depay0> handle NAL type 1
0:00:07.466031013 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal:<rtph264depay0> adding NAL to picture adapter
0:00:07.466037063 31333      0x26d80a0 DEBUG           rtph264depay gstrtph264depay.c:778:gst_rtp_h264_complete_au:<rtph264depay0> taking completed AU
0:00:07.466043230 31333      0x26d80a0 LOG             rtph264depay gstrtph264depay.c:756:gst_rtp_h264_depay_allocate_output_buffer:<rtph264depay0> want output buffer of 417 bytes
0:00:07.466361384 31333      0x26d80a0 ERROR                  libav :0:: illegal short term buffer state detected

I have tried changing many different properties of rtpjitterbuffer but it has no effect.

Does anyone know why this is happening? Is there a problem with my pipeline or could this be a bug (I am using GStreamer v1.14.4)?

Any help would be greatly appreciated as I have already spend a long time trying to solve this.

Thanks
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190126/aa914950/attachment.html>