GNOME Bugzilla – Bug 688188
videomixer: _sink_clip: GStreamer-CRITICAL **: _gst_util_uint64_scale_int: assertion `denom > 0' failed
Last modified: 2013-07-26 08:09:27 UTC
Created attachment 228794 [details] Simple python test app My application seems to work, but I do get this on the console. (python:18401): GStreamer-CRITICAL **: _gst_util_uint64_scale_int: assertion `denom > 0' failed Will attach simple python test app. Test file (to be placed in /tmp is http://www.linuxrising.org/misc/test.mkv)
(python:18464): GStreamer-CRITICAL **: _gst_util_uint64_scale_int: assertion `denom > 0' failed Program received signal SIGTRAP, Trace/breakpoint trap. [Switching to Thread 0x7fffecc60700 (LWP 18470)] g_logv (log_domain=0x32a0aada98 "GStreamer", log_level=G_LOG_LEVEL_CRITICAL, format= 0x32ac2b58fa "%s: assertion `%s' failed", args1=args1@entry=0x7fffecc5e128) at gmessages.h:101 101 void g_logv (const gchar *log_domain, (gdb) thread apply all bt
+ Trace 231167
Thread 7 (Thread 0x7fffdf7fe700 (LWP 18472))
Thread 6 (Thread 0x7fffdffff700 (LWP 18471))
Thread 5 (Thread 0x7fffecc60700 (LWP 18470))
Thread 4 (Thread 0x7fffed461700 (LWP 18469))
I see the same issue. My environment: OS: Windows/mingw. App: Custom, 'C'. GST: 1.0.4 (also occurred in 1.0.3) It only happens once at startup. It doesn't seem to cause any problem besides the message.
(In reply to comment #0) > Created an attachment (id=228794) [details] Unrelated comment, it's GLib.MainLoop instead of GObject.MainLoop.
Created attachment 243010 [details] [review] Check FPS_N to prevent zero division This fails when called from a segment event with a fake buffer that has no duration. We need to check FPS_N since on the first segment event there is no caps in the videomixer, and even on second event, we can still have dynamic framerate (0/1). I'm basing this patch on the fact that we assert but that the application still works properly.
Why would a segment arrive *before* a caps event? That must not happen
In my case the caps come first. However, the h.264 parser/decoder delivers 0/1 for the framerate. Maybe this means "variable framerate". My content is a mixture of 24000/1001 and 30000/1001 fps. I'm using "h264parse" and "avdec_h264".
(In reply to comment #5) > Why would a segment arrive *before* a caps event? That must not happen Oh, then I got it wrong, so it's caps event -> segment -> buffers ? In any case, we need to check that the numerator is not 0, since it mean dynamic framerate as exposed by Michael Rubinstein. Or maybe not having a duration while framerate is dynamic is consider invalid ? As a step back, isn't it abusing the API to create fake buffers for the purpose of calling clip ? I feel like this virtual method should have been changed in 1.0, could it be ?
Review of attachment 243010 [details] [review]: Technically, what should be checked here is the denominator. Also the root of the problem in my opinion is that caps should have been negotiated here, providing a supposedly non-zero denominator and numerator.
(In reply to comment #7) > (In reply to comment #5) > > Why would a segment arrive *before* a caps event? That must not happen > > Oh, then I got it wrong, so it's caps event -> segment -> buffers ? Yes, and before caps comes stream-start. See the order of events in gstevent.h > In any > case, we need to check that the numerator is not 0, since it mean dynamic > framerate as exposed by Michael Rubinstein. Or maybe not having a duration > while framerate is dynamic is consider invalid ? Dynamic framerate must have timestamps but not duration. > As a step back, isn't it abusing the API to create fake buffers for the purpose > of calling clip ? I feel like this virtual method should have been changed in > 1.0, could it be ? Yes, there should be no real need for fake buffers.
(In reply to comment #8) > Review of attachment 243010 [details] [review]: > > Technically, what should be checked here is the denominator. Also the root of > the problem in my opinion is that caps should have been negotiated here, > providing a supposedly non-zero denominator and numerator. Almost :) 0/1 is a valid framerate and stands for 'variable framerate'. We do need to check the numerator here, because that's the denominator in the next line, the one that causes the criticals.
I think my earlier comment was wrong. I set a breakpoint on the caps handling code, verified that it got hit and waited for the assert. However, the breakpoint was hit for a different sink that the one at the assert. The pad info at the assert: info = { finfo = 0x0, interlace_mode = GST_VIDEO_INTERLACE_MODE_PROGRESSIVE, flags = GST_VIDEO_FLAG_NONE, width = 0, height = 0, size = 0, views = 0, chroma_site = GST_VIDEO_CHROMA_SITE_UNKNOWN, colorimetry = { range = GST_VIDEO_COLOR_RANGE_UNKNOWN, matrix = GST_VIDEO_COLOR_MATRIX_UNKNOWN, transfer = GST_VIDEO_TRANSFER_UNKNOWN, primaries = GST_VIDEO_COLOR_PRIMARIES_UNKNOWN }, par_n = 0, par_d = 0, fps_n = 0, fps_d = 0, offset = {0, 1072693248, 0, 1072693248}, stride = {3, 0, 0, 0}, _gst_reserved = {0x0, 0x0, 0x0, 0x0} }, xpos = -1, ypos = -1, zorder = 0, alpha = 0, mixcol = 0xffffffff The buffer: 0 = { mini_object = { type = 36251888, refcount = 1, lockstate = 0, flags = 0, copy = 0x6144f3a4 <_gst_buffer_copy>, dispose = 0x6144dbc0 <_gst_buffer_dispose>, free = 0x6144da2c <_gst_buffer_free>, n_qdata = 0, qdata = 0x0 }, pool = 0x0, pts = 0, dts = 18446744073709551615, duration = 18446744073709551615, offset = 18446744073709551615, offset_end = 18446744073709551615
(In reply to comment #8) > Review of attachment 243010 [details] [review]: > > Technically, what should be checked here is the denominator. Didn't read the code closely enough, I thought denominator was passed as the denominator sorry. > Also the root of > the problem in my opinion is that caps should have been negotiated here, > providing a supposedly non-zero denominator and numerator. We have a similar problem in GES, when trying to render a ogv from two ogvs with a transition, oggdemux produces a segment with start equal to 0 and stop equal to the duration of the file source, where matroskademux doesn't have the same behaviour. I don't know what the correct behaviour is, but I think that segment ought not to be emitted in these circumstances.
I had a little brainstorm with ocrete yesterday, and we had that impression that there exist valid cases where event will not stick on the pads in the proper order (segment before caps). It would be nice to try and see if sorting sticky at insertion helps in this case.
Created attachment 243285 [details] [review] Sort sticky event at insertion Assuming there is legit use cases where there might not be caps, but a segment (e.g. like a BYTE segment), it might be preferrable to simply sort sticky at insertion, so when it's time to let them go, they are in the right order.
While this patch look correct it only works around the original problem that something is sending events in the wrong order. Do you know what is sending events in the wrong order here and why?
I honestly did not put time yet at figuring exactly what is going on. My hypothesis was that a byte segment stick somewhere before the type finding is completed, breaking the very stricked order that shall be respected. This scenario seemed plausible, and not really a bug. Clearly, it does not cost anything to sort the sticky, but if we don't, we should probably add some code to detect miss-ordering. Miss-ordering happens when insertion point with that new code is not the length of the array (the end). But this is still quite late detection, getting a warning if a segment stick without caps would be better (if it is invalid in all cases like byte segment).
<stormer> slomo: I was wondering if it was plausible to get a segment without caps during the type finding ? like a byte segment <slomo> stormer: yes, like for filesrc you never get caps <slomo> stormer: but typefind should first forward caps, then segment <slomo> stormer: and filesrc should never push caps after a segment <stormer> slomo: we'll have to check that, never the less, we need code to catch this, because the way it is done right now, it is really easy to break the order, and the effect is visible much later, after the fact <slomo> stormer: i'm fine with a check in gstpad that causes a g_warning() if events happen out of order <slomo> stormer: but silently fixing that up is just covering bugs elsewhere <stormer> possibly, as said my filling was that there is cases where a segment will stick, and (without flush) will get replaced by a pair of caps and segment, but that leads to miss-ordering <stormer> s/filling/feeling/ <stormer> slomo: it's also difficult to control when you try to do dynamic linking <slomo> stormer: do you have a scenario where that could happen but all elements are doing their job correctly? <__tim> if I'm not mistaken you only wrote that you and ocrete "had a feeling" it could happen legitimately, but you didn't provide more details :) <stormer> slomo: that's what I said, it takes hours to analyse what going on, when I'll have to revisit, I just thought that one of you knew if such a scenario exist or not <__tim> when you link the sticky events should be dispatched in the right order (and a predefined order) - is that not <slomo> stormer: i can't think of any, sorry :) but feel free to push a change similar to your latest, that doesn't force the order but instead does a g_warning()
Ok, I've been experimenting with traces. Non-related finding is that oggmux always sends it's segment beofre the caps (See bug #699763). This floods a little bit while trying to find this issue. By adding segment and caps specific check, I managed to detect the right moment a miss-ordering is produced. I'm out of time for today, but I have found that the miss-ordering happens when cached events get sent in gst_video_decoder_prepare_finish_frame() (this is the video decoder base class). To be continued ...
Created attachment 243398 [details] [review] Sort and warn if sticky event arrives in the wrong order. I've just replaced the patch with one that is not silent. Also, for the posterity: <ocrete> __tim: slomo: the use-case for caps-after-segment is ... if you have filesrc ! capsfilter ! ... ... and you manually set the caps once it's playing <slomo> ocrete: is there any good reason to do that? but yes, then it happens :) <ocrete> slomo: can't think of any, but I'm pretty sure it's just a matter of time before it happens
Review of attachment 243398 [details] [review]: ::: gst/gstpad.c @@ +4437,3 @@ + + if (type < GST_EVENT_TYPE (ev->event)) { + GST_WARNING_OBJECT (pad, "Sticky event miss-ordering detected"); Make this a g_warning() that also includes the name of the pad and parent (GST_DEBUG_PAD_NAME). And isn't it mis-ordering with one 's'? :)
Created attachment 243556 [details] [review] [PATCH] pad: Detect, fix and warn when sticky events are in wrong order We can prevent buggy element from causing other elements to fail or crash by sorting sticky event at insertion. In this case, we also warn as this is not supposed to happen. See: https://bugzilla.gnome.org/show_bug.cgi?id=688188 --- gst/gstpad.c | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-)
Comment on attachment 243556 [details] [review] [PATCH] pad: Detect, fix and warn when sticky events are in wrong order commit a68e33712eeb9104a418a0882725ac2290f29a51 Author: Nicolas Dufresne <nicolas.dufresne@collabora.co.uk> Date: Tue May 7 21:53:37 2013 -0400 pad: Detect, fix and warn when sticky events are in wrong order We can prevent buggy element from causing other elements to fail or crash by sorting sticky event at insertion. In this case, we also warn as this is not supposed to happen. See: https://bugzilla.gnome.org/show_bug.cgi?id=688188
*** Bug 699952 has been marked as a duplicate of this bug. ***
The new warning I have introduced is a little too agressive. TAG, BUFFERSIZE, SINK_MESSAGE, and TOC have no order restriction. If that is fine, I would keep inserting these sorted, and then warn if the event type we are inserting is before an event type smaller then SEGMENT event.
Created attachment 243635 [details] [review] [PATCH] pad: Only inforce STREAM_START, CAPS and SEGMENT ordering Previous patch was inforcing a complete ordering of the sticky events, while in fact, only STREAM_START, CAPS and SEGMENT events need proper ordering. See: https://bugzilla.gnome.org/show_bug.cgi?id=688188 --- gst/gstpad.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-)
Created attachment 243645 [details] [review] [PATCH] pad: Improve warning message naming events type name With this patch, message should look like ¨Sticky event misordering, got 'caps' before 'stream-start'¨ making it faster to debug. https://bugzilla.gnome.org/show_bug.cgi?id=688188 --- gst/gstpad.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-)
Any news on this? Is still something missing here?
Would have to test, but I think the only remaining is the case where we have a 0/1 fps.
This bug doesn't appear in our test cases anymore, and with Nicolas' patch I can't see it happening again anytime soon :)
I fixed some 0/1 fps issues yesterday in videomixer.
So let's get rid of it?