rtph264depay: Badly frame streams coming from Safari 12 (due to marker bit)
Creating issue base on mailing list message (quoted below). There seems to be issues with rtph264depay handling streams coming from Safari 12. I have managed to reproduce this issue, and found out that the problem is around the interpretation of the marker. I still need to figure-out if the marker are miss-placed by Safari or if it's rtph264depay interpreting them wrong. This is not a regression as it was already causing issues in 1.14. Ignoring the marker in the code makes this stream decode properly.
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: expected #70, got #70, gap of 0 0:00:07.425939062 31333 0x27669e0 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:3084:gst_rtp_jitter_buffer_chain: Clearing gap packets 0:00:07.425968309 31333 0x27669e0 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:3230:gst_rtp_jitter_buffer_chain: 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: 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: 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: expected #71, got #71, gap of 0 0:00:07.430347687 31333 0x27669e0 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:3084:gst_rtp_jitter_buffer_chain: 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: 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: 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: 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: receiving 811 bytes 0:00:07.464843846 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:1046:gst_rtp_h264_depay_process: NRI 1, Type 24 0:00:07.464853441 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal: handle NAL type 1 0:00:07.464859635 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:904:gst_rtp_h264_depay_handle_nal: start 1, complete 1 0:00:07.464864758 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal: adding NAL to picture adapter 0:00:07.464873130 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal: handle NAL type 1 0:00:07.464878908 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:904:gst_rtp_h264_depay_handle_nal: start 1, complete 0 0:00:07.464884010 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal: adding NAL to picture adapter 0:00:07.464895585 31333 0x26d80a0 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:3517:pop_and_push_next: 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: 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: receiving 1058 bytes 0:00:07.464918633 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:1046:gst_rtp_h264_depay_process: NRI 1, Type 24 0:00:07.464925747 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal: handle NAL type 1 0:00:07.464930885 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal: adding NAL to picture adapter 0:00:07.464936129 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:778:gst_rtp_h264_complete_au: taking completed AU 0:00:07.464941830 31333 0x26d80a0 LOG rtph264depay gstrtph264depay.c:756:gst_rtp_h264_depay_allocate_output_buffer: want output buffer of 1458 bytes 0:00:07.466015023 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:844:gst_rtp_h264_depay_handle_nal: handle NAL type 1 0:00:07.466031013 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:913:gst_rtp_h264_depay_handle_nal: adding NAL to picture adapter 0:00:07.466037063 31333 0x26d80a0 DEBUG rtph264depay gstrtph264depay.c:778:gst_rtp_h264_complete_au: taking completed AU 0:00:07.466043230 31333 0x26d80a0 LOG rtph264depay gstrtph264depay.c:756:gst_rtp_h264_depay_allocate_output_buffer: 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