GNOME Bugzilla – Bug 783443
rtp: fix gst_rtp_buffer_ext_timestamp taking into account backwards
Last modified: 2018-10-27 11:02:15 UTC
I have noticed that gst_rtp_buffer_ext_timestamp utility do not manage backward timestamps properly. I will use a test to show an example and a proposal patch to fix it.
Created attachment 353197 [details] [review] rtp: add tests for RTP utilities Patch adding base tests for RTP utilities.
Created attachment 353198 [details] [review] rtp: fix gst_rtp_buffer_ext_timestamp taking into account backwards Fix and test backward timestamps.
Review of attachment 353198 [details] [review]: See comment in the code. ::: gst-libs/gst/rtp/gstrtpbuffer.c @@ +1293,3 @@ + /* timestamp went forwards more than allowed, we unwrap around and get + * updated extended timestamp. */ + result += (G_GUINT64_CONSTANT (1) << 32); We should check if we already did a wrap around before decreasing the 32 most significative bits. Otherwise we'll be overflowing the value.
Review of attachment 353197 [details] [review]: This test should go into tests/check/libs/rtp.c ::: tests/check/generic/rtp.c @@ +33,3 @@ + + gst_rtp_buffer_ext_timestamp (&ext_ts, 0); + fail_unless (ext_ts == 0x100000000); Is this G_MAXUINT32 + 1 ? If so, please write is as such so it's a bit more readable. @@ +36,3 @@ + + gst_rtp_buffer_ext_timestamp (&ext_ts, 90000); + fail_unless (ext_ts == (0x100000000 + 90000)); Same here, I assume this is G_MAXUINT32 + 1 + 90000 ?
Review of attachment 353198 [details] [review]: ::: gst-libs/gst/rtp/gstrtpbuffer.c @@ +1293,3 @@ + /* timestamp went forwards more than allowed, we unwrap around and get + * updated extended timestamp. */ + result -= (G_GUINT64_CONSTANT (1) << 32); I'm also not convinced that we shoudl ever make ext go backwards, which is the result of this patch, as result is store into *ext in the end.
This looks related to https://bugzilla.gnome.org/show_bug.cgi?id=780446 And yes, the ext timestamp should never ever go backwards.
Sebastian, thanks for pointing to the other bugs. It seems that we have come across the same issue.
Created attachment 353314 [details] [review] rtp: add tests for RTP utilities Replace 0x100000000 to (G_MAXUINT32 + 1)
Created attachment 353315 [details] [review] rtp: fix gst_rtp_buffer_ext_timestamp taking into account backwards Update doc
Created attachment 353321 [details] [review] rtp: fix gst_rtp_buffer_ext_timestamp taking into account backwards Take into account impossible unwrapping and update doc consequently.
If we stick to the doc, then we must fix the jitter buffer to not use this function before pushing buffers out as otherwise it may result in calling it out of order. It also means that rtpsession can't use it. And then it's not very useful anywhere. I think instead it should allow going backwards by under MAXUINT32 and then it will be useful and fix the documentation to explain that.
I agree with you Olivier and is what I did in the attached patches. What do you think about them?
I merged both of yoru patches and pushed it as one patch: commit bae36361978d0caca2dcce06d835ffa924a91ea2 Author: Miguel Paris <mparisparis@gmail.com> Date: Mon Jun 5 18:11:42 2017 +0200 rtp: fix gst_rtp_buffer_ext_timestamp taking into account backwards If timestamp goes forwards more than allowed, we consider that the timestamp belongs to the previous counting, so the extended timestamp is unwrapped. https://bugzilla.gnome.org/show_bug.cgi?id=783443
I am seeing that the fix for this problem makes some cameras get stuck with RTCP.SR RTP-timestamp stuck close to 0 (below 22000 and above 4294650000) since the gst_rtp_buffer_ext_timestamp() function keeps returning zero in some cases when a new stream is started. Is that anything anyone else has noticed? Do you have a suggested fix?
(In reply to Kenneth Ekman from comment #14) > I am seeing that the fix for this problem makes some cameras get stuck with > RTCP.SR RTP-timestamp stuck close to 0 (below 22000 and above 4294650000) > since the gst_rtp_buffer_ext_timestamp() function keeps returning zero in > some cases when a new stream is started. > > Is that anything anyone else has noticed? > > Do you have a suggested fix? I should maybe clarify that the print "Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp" starts spamming when this happens as well.
Do you know if the packets are out of order ? (Or if this is a B-Frames enabled video stream?)
I am no RTP/RTCP expert, but to me nothing indicates that frames are out of order. I can provoke it by running gst-launch-1.0 rtspsrc location='rtsp://<ip>/media/?video=0&audio=0&event=on' which is some sort of test data generator as well
(In reply to Kenneth Ekman from comment #17) > gst-launch-1.0 rtspsrc location='rtsp://<ip>/media/?video=0&audio=0&event=on' Can you capture the stream with something like: "tcpdump -wcapture.pcap -s0 udp" and attach it here?
I tried using pcapdump yesterday but for some reason I didn't find any RTP traffic in those, but I can do one better, since I modified the code to give some extra prints that might be helpful. I modified the gst_rtp_buffer_ext_timestamp() in rtpsource.c in this way: guint64 gst_rtp_buffer_ext_timestamp (guint64 * exttimestamp, guint32 timestamp) { guint64 result, ext; static int print_count = 1000; g_return_val_if_fail (exttimestamp != NULL, -1); ext = *exttimestamp; if (ext == -1) { result = timestamp; GST_WARNING("gst_rtp_buffer_ext_timestamp() init time (-1) %u.", timestamp); print_count = 0; } else { /* pick wraparound counter from previous timestamp and add to new timestamp */ result = timestamp + (ext & ~(G_GUINT64_CONSTANT (0xffffffff))); if (print_count < 20) { GST_WARNING("gst_rtp_buffer_ext_timestamp() ext=%llu result=%llu ts=%u", ext, result, timestamp); print_count++; } /* check for timestamp wraparound */ if (result < ext) { guint64 diff = ext - result; if (diff > G_MAXINT32) { /* timestamp went backwards more than allowed, we wrap around and get * updated extended timestamp. */ result += (G_GUINT64_CONSTANT (1) << 32); } } else { guint64 diff = result - ext; if (print_count < 20) { GST_WARNING("gst_rtp_buffer_ext_timestamp(). diff=%llu ext=%llu result=%llu ts=%u", diff, ext, result, timestamp); } //syslog(LOG_INFO, "gst_rtp_buffer_ext_timestamp(). diff=%llu ext=%llu result=%llu ts=%u", diff, ext, result, timestamp); if (diff > G_MAXINT32) { if (result < (G_GUINT64_CONSTANT (1) << 32)) { GST_WARNING ("Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=%llu = (result:%llu - ext:%llu) %d", diff, result, ext, print_count); return 0; } else { /* timestamp went forwards more than allowed, we unwrap around and get * updated extended timestamp. */ result -= (G_GUINT64_CONSTANT (1) << 32); /* We don't want the extended timestamp storage to go back, ever */ return result; } } } } *exttimestamp = result; return result; } And then enabled logs which gave me this debug log: :01:31.375552516 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:310:rtp_source_init: init 0:01:31.376172868 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:420:rtp_source_create_stats: stats have_sr:0 ntp:0 rtp:0 0:01:31.376297632 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:455:rtp_source_create_stats: stats is_sender:0 internal:0 0:01:31.376570109 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:1434:rtp_source_process_rb: got RB packet: SSRC d137e7c8, FL 0, PL 0, HS 13481, jitter 208, LSR 0000:0000, DLSR 0000:0000 0:01:31.376643852 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:1461:rtp_source_process_rb: NTP 7d84:ea07, round trip 0000:0000 0:01:33.407796223 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1508:rtp_source_get_new_sr: last_rtime 16:50:53.823602000, last_rtptime 2921979845 0:01:33.407926541 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1525:rtp_source_get_new_sr: running_time 16:50:53.950158501, diff +0:00:00.126556501 0:01:33.407993301 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1545:rtp_source_get_new_sr: NTP df697d86:f2464990, RTP 2921991235 0:01:33.408040838 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1381:rtp_source_process_sr: got SR packet: SSRC 6c4fce98, NTP df697d86:f2464990, RTP 2921991235, PC 93, OC 79703 0:01:33.412803901 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:420:rtp_source_create_stats: stats have_sr:1 ntp:16098536361556330896 rtp:2921991235 0:01:33.413959887 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:455:rtp_source_create_stats: stats is_sender:1 internal:1 0:01:35.927665932 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:1434:rtp_source_process_rb: got RB packet: SSRC d137e7c8, FL 0, PL 0, HS 13527, jitter 27, LSR 7d86:f246, DLSR 0002:837f 0:01:35.927810338 13417 0x74a3d1b0 DEBUG rtpsource rtpsource.c:1461:rtp_source_process_rb: NTP 7d89:7765, round trip 0000:01a0 0:01:38.209085064 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1508:rtp_source_get_new_sr: last_rtime 16:50:58.628891000, last_rtptime 2922412321 0:01:38.209644704 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1525:rtp_source_get_new_sr: running_time 16:50:58.751568058, diff +0:00:00.122677058 0:01:38.209882484 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1545:rtp_source_get_new_sr: NTP df697d8b:bf6f7e3d, RTP 2922423361 0:01:38.209984579 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:1381:rtp_source_process_sr: got SR packet: SSRC 6c4fce98, NTP df697d8b:bf6f7e3d, RTP 2922423361, PC 141, OC 115062 0:01:38.210617558 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:420:rtp_source_create_stats: stats have_sr:1 ntp:16098536382178229821 rtp:2922423361 0:01:38.210734410 13417 0x20a9a60 DEBUG rtpsource rtpsource.c:455:rtp_source_create_stats: stats is_sender:1 internal:1 0:01:38.464507519 13417 0x74921800 DEBUG rtpsource rtpsource.c:351:rtp_source_finalize: finalize 0:01:38.464825193 13417 0x74921800 DEBUG rtpsource rtpsource.c:351:rtp_source_finalize: finalize 0:01:43.107109562 13417 0x74903980 DEBUG rtpsource rtpsource.c:276:rtp_source_reset: reset 0:01:43.107351368 13417 0x74903980 DEBUG rtpsource rtpsource.c:310:rtp_source_init: init 0:01:43.112255198 13417 0x74903980 DEBUG rtpsource rtpsource.c:822:rtp_source_update_caps: got payload 98 0:01:43.113232553 13417 0x74903980 DEBUG rtpsource rtpsource.c:829:rtp_source_update_caps: got clock-rate 90000 0:01:43.113842709 13417 0x74903980 DEBUG rtpsource rtpsource.c:838:rtp_source_update_caps: got seqnum-offset 12869 0:01:43.114307516 13417 0x74903980 DEBUG rtpsource rtpsource.c:420:rtp_source_create_stats: stats have_sr:0 ntp:0 rtp:0 0:01:43.114956742 13417 0x74903980 DEBUG rtpsource rtpsource.c:455:rtp_source_create_stats: stats is_sender:0 internal:1 0:01:43.117941375 13417 0x74903980 DEBUG rtpsource rtpsource.c:1081:update_receiver_stats: received first packet 0:01:43.118929579 13417 0x74903980 DEBUG rtpsource rtpsource.c:1018:init_seq: base_seq 12869 0:01:43.119544959 13417 0x74903980 WARN default gstrtpbuffer.c:1279:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() init time (-1) 208249398. 0:01:43.181388907 13417 0x2093090 DEBUG rtpsource rtpsource.c:822:rtp_source_update_caps: got payload 98 0:01:43.181542976 13417 0x2093090 DEBUG rtpsource rtpsource.c:829:rtp_source_update_caps: got clock-rate 90000 0:01:43.181605056 13417 0x2093090 DEBUG rtpsource rtpsource.c:838:rtp_source_update_caps: got seqnum-offset 12870 0:01:43.182787457 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=208249398 result=3917904230 ts=3917904230 0:01:43.182947905 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3709654832 ext=208249398 result=3917904230 ts=3917904230 0:01:43.183023936 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3709654832 = (result:3917904230 - ext:208249398) 1 0:01:44.168499877 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917993368 ts=3917993368 0:01:44.169888692 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917993368 ext=0 result=3917993368 ts=3917993368 0:01:44.178445591 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917993368 = (result:3917993368 - ext:0) 2 0:01:44.183058848 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917994751 ts=3917994751 0:01:44.183195251 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917994751 ext=0 result=3917994751 ts=3917994751 0:01:44.183291742 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917994751 = (result:3917994751 - ext:0) 3 0:01:44.183671362 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917994751 ts=3917994751 0:01:44.183946057 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917994751 ext=0 result=3917994751 ts=3917994751 0:01:44.184031228 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917994751 = (result:3917994751 - ext:0) 4 0:01:44.188884042 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917995281 ts=3917995281 0:01:44.189032189 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917995281 ext=0 result=3917995281 ts=3917995281 0:01:44.189095814 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917995281 = (result:3917995281 - ext:0) 5 0:01:44.192241405 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917995578 ts=3917995578 0:01:44.192893085 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917995578 ext=0 result=3917995578 ts=3917995578 0:01:44.193222023 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917995578 = (result:3917995578 - ext:0) 6 0:01:44.196872319 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917995843 ts=3917995843 0:01:44.208496302 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917995843 ext=0 result=3917995843 ts=3917995843 0:01:44.209510260 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917995843 = (result:3917995843 - ext:0) 7 0:01:44.210317310 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917995985 ts=3917995985 0:01:44.210769165 13417 0x2093090 WARN default gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp(). diff=3917995985 ext=0 result=3917995985 ts=3917995985 0:01:44.211106777 13417 0x2093090 WARN default gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping took place yet. Returning 0 without updating extended timestamp. diff=3917995985 = (result:3917995985 - ext:0) 8 0:01:44.234353079 13417 0x2093090 WARN default gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp: gst_rtp_buffer_ext_timestamp() ext=0 result=3917999357 ts=3917999357
It is possible to set the suspend mode for a rtsp-media in gst-rtsp-server and that is something we do for live pipelines. We use a suspend mode called reset, which will set the state of the pipeline to NULL (It was introduced to get rid of of the preroll buffers produced in RTSP DESCRIBE). The RTP timestamp of the first buffer is based on a random offset, which is generated when rtp*pay goes from READY to PAUSED (it is possible to configure this manually). The RTP buffer generated in DESCRIBE and the one from PLAY have RTP timestamps. If the two timestamps differ too much, gst_rtp_buffer_ext_timestamp() will fail and return 0 (0 will then be kept and used as input for the next buffer, and the problem will occur for the next buffer as well). To me the problem appears to be that the timestamp generated in DESCRIBE is still kept in RTPSource (stored in RTPSource.last_rtptime). GstRtpSession will not reset it's internal RTPSession object when the pipeline goes to READY. I think the solution should be to 1) reset last_rtptime in RTPSource when GstRtpSession goes from PAUSED to READY, or 2) manually configure the timestamp offset for rtp*pay. To me option 1) sound better. Any other opinions? Anyway, I don't think the merged patch is wrong, it just exposed another problem.
See https://bugzilla.gnome.org/show_bug.cgi?id=797304