GNOME Bugzilla – Bug 730417
rtspt: no timestamp from some rtsp source over tcp
Last modified: 2014-10-21 10:01:31 UTC
the rtsp over tcp generated by a network camera give all video buffers without timestamp: gst-launch-1.0 -vmt rtspsrc location="rtspt://" ! rtph264depay ! fakesink silent=false show for each video buffer: /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (7241 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00002000 delta-unit ) 0x7fae600eac60 so no timestamp are setted for audio ts are setted correctly: gst-launch-1.0 -vmt rtspsrc location="rtspt://" ! rtpmp4gdepay ! fakesink silent=false show: /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (384 bytes, dts: none, pts: 0:00:02.562682913, duration: none, offset: 39, offset_end: -1, flags: 00004000 tag-memory ) 0x7f53540cd300 here is a dump: http://195.250.34.59/temp/rtsp.dump captured with gst-launch-1.0 -vmt rtspsrc location="rtspt://...." ! filesink location=/tmp/rtsp.dump here are the caps: /GstPipeline:pipeline0/GstFileSink:filesink0.GstPad:sink: caps = "application/x-rtp\,\ media\=\(string\)video\,\ payload\=\(int\)35\,\ clock-rate\=\(int\)90000\,\ encoding-name\=\(string\)H264\,\ packetization-mode\=\(string\)1\,\ profile-level-id\=\(string\)4d0029\,\ sprop-parameter-sets\=\(string\)\"Z00AKZpmA8ARPy4C1BQEFAg\\\=\\\,aO48gA\\\=\\\=\"\,\ a-recvonly\=\(string\)\"\"\,\ ssrc\=\(uint\)502464689\,\ npt-start\=\(guint64\)0\,\ play-speed\=\(double\)1\,\ play-scale\=\(double\)1" /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0.GstGhostPad:recv_rtp_src_0_502464689_35.GstProxyPad:proxypad4: caps = "application/x-rtp\,\ media\=\(string\)video\,\ payload\=\(int\)35\,\ clock-rate\=\(int\)90000\,\ encoding-name\=\(string\)H264\,\ packetization-mode\=\(string\)1\,\ profile-level-id\=\(string\)4d0029\,\ sprop-parameter-sets\=\(string\)\"Z00AKZpmA8ARPy4C1BQEFAg\\\=\\\,aO48gA\\\=\\\=\"\,\ a-recvonly\=\(string\)\"\"\,\ ssrc\=\(uint\)502464689\,\ npt-start\=\(guint64\)0\,\ play-speed\=\(double\)1\,\ play-scale\=\(double\)1" /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0/GstRtpBin:manager.GstGhostPad:recv_rtp_src_0_502464689_35.GstProxyPad:proxypad3: caps = "application/x-rtp\,\ media\=\(string\)video\,\ payload\=\(int\)35\,\ clock-rate\=\(int\)90000\,\ encoding-name\=\(string\)H264\,\ packetization-mode\=\(string\)1\,\ profile-level-id\=\(string\)4d0029\,\ sprop-parameter-sets\=\(string\)\"Z00AKZpmA8ARPy4C1BQEFAg\\\=\\\,aO48gA\\\=\\\=\"\,\ a-recvonly\=\(string\)\"\"\,\ ssrc\=\(uint\)502464689\,\ npt-start\=\(guint64\)0\,\ play-speed\=\(double\)1\,\ play-scale\=\(double\)1" and here a dump captured with wireshark: http://195.250.34.59/temp/rtsptdump.pcapng wireshark show timing information
Seems to work fine for me, can you provide a gdp dump like this: gst-launch-1.0 -vmt rtspsrc location="rtspt://" ! gdppay ! filesink location=rtsp.gdp
Created attachment 279088 [details] gdp dump using this pipeline: gst-launch-1.0 -vmt filesrc location=/tmp/rtsp.gdp ! gdpdepay ! rtph264depay ! fakesink silent=false you can see no ts for all the frames, tested with today git master
using GST_DEBUG=*:5 I can see logs like these: 0:00:07.881543222 2732 0x1e9f770 DEBUG rtspsrc gstrtspsrc.c:4425:gst_rtspsrc_handle_data:<rtspsrc0> pushing data of size 58 on channel 0 0:00:07.881575236 2732 0x1e9f770 DEBUG GST_CLOCK gstclock.c:950:gst_clock_get_internal_time:<GstSystemClock> internal time 0:49:30.374767598 0:00:07.881603059 2732 0x1e9f770 DEBUG GST_CLOCK gstclock.c:995:gst_clock_get_time:<GstSystemClock> adjusted time 0:49:30.374767598 0:00:07.881628698 2732 0x1e9f770 DEBUG GST_CLOCK gstclock.c:950:gst_clock_get_internal_time:<GstSystemClock> internal time 0:49:30.374821546 0:00:07.881650623 2732 0x1e9f770 DEBUG GST_CLOCK gstclock.c:995:gst_clock_get_time:<GstSystemClock> adjusted time 0:49:30.374821546 0:00:07.881685778 2732 0x1e9f770 DEBUG rtpssrcdemux gstrtpssrcdemux.c:625:gst_rtp_ssrc_demux_chain:<rtpssrcdemux0> received buffer of SSRC 1bdd002d 0:00:07.881710895 2732 0x1e9f770 DEBUG default gstsegment.c:479:gst_segment_to_running_time: invalid position (-1) 0:00:07.881731061 2732 0x1e9f770 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2122:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> Received packet #1857 at time 99:99:99.999999999, discont 0 0:00:07.881758198 2732 0x1e9f770 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2069:calculate_jitter:<rtpjitterbuffer0> no dts or no clock-rate, can't calculate jitter 0:00:07.881777482 2732 0x1e9f770 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2170:gst_rtp_jitter_buffer_chain:<rtpjitterbuffer0> expected #1857, got #1857, gap of 0 0:00:07.881799633 2732 0x1e9f770 DEBUG rtpjitterbuffer rtpjitterbuffer.c:436:calculate_skew: Taking new base time 99:99:99.999999999 0:00:07.881821257 2732 0x1e9f770 DEBUG rtpjitterbuffer rtpjitterbuffer.c:464:calculate_skew: extrtp 1133520752, gstrtp 3:29:54.675022222, base 3:29:48.674266666, send_diff 0:00:06.000755556 0:00:07.881855711 2732 0x1e9f770 DEBUG rtpjitterbuffer rtpjitterbuffer.c:619:calculate_skew: skew 0, out 99:99:99.999999999
Created attachment 279461 [details] log that show no timestamp information log captured from this pipeline: gst-launch-1.0 -vmt rtspsrc location=rtspt://... ! rtph264depay ! fakesink silent=false with GST_DEBUG=rtp*:6
testing several times the pipeline "rtspsrc ! rtph264depay ! fakesink" I can see: - sometime works as expected, buffers received from fakesink have valid pts - most of the time the first buffer received from fakesink has a valid pts while all the others have invalid pts (you can see this in the log previously attached)
just in case the first dump was captured one of the time the timestamp are correctly detected here is a new one (that show correct timing inside wireshark/irtspparse): http://195.250.34.59/temp/730417.pcap please let me know if you need other infos
Created attachment 279786 [details] [review] possible patch Does this fix the issue for you?
the patch seems fine, thanks!
Created attachment 280543 [details] timestamp go backward after more tests with this patch applied I see something like this: /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (678 bytes, dts: none, pts: 0:00:00.228670476, duration: none, offset: -1, offset_end: -1, flags: 00002000 delta-unit ) 0x7f3f3c04eb20 0:00:02.530479774 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 75, dts 99:99:99.999999999, pts 0:00:00.328814920 0:00:02.530517325 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 76, dts 99:99:99.999999999, pts 0:00:00.328814920 0:00:02.530555136 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 77, dts 99:99:99.999999999, pts 0:00:00.328814920 0:00:02.530591795 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 78, dts 99:99:99.999999999, pts 0:00:00.328814920 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (3732 bytes, dts: none, pts: 0:00:00.328814920, duration: none, offset: -1, offset_end: -1, flags: 00002000 delta-unit ) 0x7f3f3c04e900 0:00:02.530690962 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 79, dts 99:99:99.999999999, pts 0:00:00.295426032 0:00:02.530728252 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 80, dts 99:99:99.999999999, pts 0:00:00.295426032 0:00:02.530762931 2462 0x7f3f3c01ea30 DEBUG rtpjitterbuffer gstrtpjitterbuffer.c:2540:pop_and_push_next:<rtpjitterbuffer0> Pushing buffer 81, dts 99:99:99.999999999, pts 0:00:00.295426032 /GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (1514 bytes, dts: none, pts: 0:00:00.295426032, duration: none, offset: -1, offset_end: -1, flags: 00002000 delta-unit ) 0x7f3f3c05c8e0 so the timestamps go backward, attached full log taken with GST_DEBUG=*jitter*:5
This looks correct, timestamps can go backwards for h264. What is the problem?
the patch look correct, wireshark show that rtptime go backward too so nothing wrong with rtsp over tcp, great! the problem now is in the muxer (matroskamux), I receive these buffers: ts: 23301032087 size: 80480 => this is a keyframe ts: 23167509865 size: 2399 => this buffer should go with the previous keyframe not the one above since has a lower timestamp I suppose ts: 23234265420 size: 508 => this buffer should go with the previous keyframe not the one above since has a lower timestamp I suppose ts: 23501332087 size: 4475 saving the file with matroskamux I see something like this: (fakesink0:sink) (80480 bytes, timestamp: 0:00:23.301000000 (fakesink0:sink) (2399 bytes, timestamp: 0:00:04.204000000 => what???? (fakesink0:sink) (508 bytes, timestamp: 0:00:04.271000000 => what???? (fakesink0:sink) (4475 bytes, timestamp: 0:00:23.501000000 for now my solution, not ideal, is to drop frames that has big negative timestamp gap using a custom element between the muxer and the filesink, my pipelines: rtspsrc ! rtph264depay ! h264parse ! appsink appsrc ! matroskamux streamable=true ! filesink to extract the above timestamp from the saved mkv file I use: filesrc ! matroskademux ! fakesink
doing some other test I see something like this: (fakesink0:sink) (12582 bytes, timestamp: 0:10:33.332981917 and then the next buffer: (fakesink0:sink) (4162 bytes, timestamp: 26:41:16.917315250 I don't have wireshark log to understand if the diff was caused by the camera or by a problem in gstreamer
patch tested since some weeks with no problem, the muxer issue reported happen in 0.10 only, 1.x is fine
what about this patch? Can be included? Seems to work in my use case
commit 2e7f5c08cfb3315fe335455b40c5627ed365357f Author: Wim Taymans <wtaymans@redhat.com> Date: Wed Jul 2 17:50:35 2014 +0200 jitterbuffer: rework resync handling Add a need-resync state, this is when we need to try to lock on to a time/RTPtime pair. Always check the RTP timestamps and if they go backwards, mark ourselves as need-resync. Only resync when need-resync is TRUE and we have a valid time. Otherwise we keep the old values. This avoids locking on to an invalid time and causing us to timestamp everything with -1. Fixes https://bugzilla.gnome.org/show_bug.cgi?id=730417