GNOME Bugzilla – Bug 758928
qtdemux: letting flushes pass downstream on upstream offset seeks
Last modified: 2015-12-22 15:57:09 UTC
i have test with gst 1.6.1 stabel and all ok playing the https mp4 works now i test with the latest git version i get this info and gst-launch is blocking GST_DEBUG_NO_COLOR=1 GST_DEBUG=dvbvideosink:4 gst-launch-1.0 playbin uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 Setting pipeline to PAUSED ... Pipeline is PREROLLING ... 0:00:00.590088407 2882 0x2acb20 INFO dvbvideosink gstdvbvideosink.c:1954:gst_dvbvideosink_change_state:<dvbvideosink0> GST_STATE_CHANGE_NULL_TO_READY (gst-launch-1.0:2882): GStreamer-WARNING **: adding flushing pad 'src_1' to running element 'decodebin0', you need to use gst_pad_set_active(pad,TRUE) before adding it. any idea that is wrong
Looks like the dvbvideosink element fails to activate a pad before adding it.
Yes, this looks like a bug in dvbvideosink which is a 3rd party element. Please report this problem to whoever provided this element.
There are no changes in dvbvideosink lately, nothing related with pads. Here is the dvbmediasink: https://github.com/OpenPLi/gst-plugin-dvbmediasink/blob/gst-1.0/gstdvbvideosink.c Any idea what might cause that?
I don't have the hardware to reproduce it here, so you'll have to debug this yourself unfortunately. git bisect should help to find the problem, I can't think of anything specific in decodebin/playbin that could've caused this.
Playing the file locally there is no problem. I think that suggests that problem is somewhere else, right? (eg souphttpsrc?) # GST_DEBUG_NO_COLOR=1 GST_DEBUG=dvbvideosink:4 gst-launch-1.0 playbin uri=file:///media/usb/video-sd.mp4 Setting pipeline to PAUSED ... Pipeline is PREROLLING ... WARNING: from element /GstPlayBin:playbin0/GstPlaySink:playsink: No volume control found Additional debug info: /opt/openpli/openpligst/build/tmp/work/mips32el-oe-linux/gstreamer1.0-plugins-base/1.7+gitAUTOINC+71505dfa24-r22/git/gst/playback/gstplaysink.c(2852): gen_audio_chain (): /GstPlayBin:playbin0/GstPlaySink:playsink: Volume/mute is not available 0:00:00.672978481 783 0x74f5a060 INFO dvbvideosink gstdvbvideosink.c:1370:gst_dvbvideosink_set_caps:<dvbvideosink0> caps = video/x-h264, stream-format=(string)avc, alignment=(string)au, level=(string)3, profile=(string)main, codec_data=(buffer)014d401effe10018674d401eeca06c1ef37808800000030080000019078b16cb01000468ef85f2, width=(int)854, height=(int)480, framerate=(fraction)25/1, pixel-aspect-ratio=(fraction)1/1 0:00:00.674824814 783 0x74f5a060 INFO dvbvideosink gstdvbvideosink.c:1472:gst_dvbvideosink_set_caps:<dvbvideosink0> H264 have codec data..! 0:00:00.675400851 783 0x74f5a060 INFO dvbvideosink gstdvbvideosink.c:1498:gst_dvbvideosink_set_caps:<dvbvideosink0> H264 main profile@3.0 0:00:00.675992999 783 0x74f5a060 INFO dvbvideosink gstdvbvideosink.c:1554:gst_dvbvideosink_set_caps:<dvbvideosink0> MIMETYPE video/x-h264 -> STREAMTYPE_MPEG4_H264 Pipeline is PREROLLED ... Setting pipeline to PLAYING ... New clock: GstSystemClock Got EOS from element "playbin0". Execution ended after 0:04:46.336278243 Setting pipeline to PAUSED ... Setting pipeline to READY ... Setting pipeline to NULL ... Freeing pipeline ...
It seems the error appears after response 206: Partial Content. GST_DEBUG_NO_COLOR=1 GST_DEBUG=*http*:5 gst-launch-1.0 playbin uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 .... 0:00:02.986768628 814 0x9207b0 DEBUG souphttpsrc gstsouphttpsrc.c:1480:gst_soup_http_src_got_chunk_cb:<source> We're EOS now 0:00:02.988100443 814 0x9207b0 DEBUG souphttpsrc gstsouphttpsrc.c:1402:gst_soup_http_src_chunk_allocator:<source> alloc 4096 bytes <= 231708 0:00:02.988782850 814 0x9207b0 DEBUG souphttpsrc gstsouphttpsrc.c:1296:gst_soup_http_src_got_body_cb:<source> got body 0:00:02.990358851 814 0x9207b0 INFO souphttpsrc gstsouphttpsrc.c:1316:gst_soup_http_src_finished_cb:<source> finished, io status: 2 0:00:02.993194666 814 0x9207b0 INFO souphttpsrc gstsouphttpsrc.c:1505:gst_soup_http_src_response_cb:<source> got response 206: Partial Content buffering... 100% (gst-launch-1.0:814): GStreamer-WARNING **: adding flushing pad 'src_1' to running element 'decodebin0', you need to use gst_pad_set_active(pad,TRUE) before adding it. 0:00:03.057688555 814 0x863e30 DEBUG souphttpsrc gstsouphttpsrc.c:1865:gst_soup_http_src_unlock:<source> unlock() 0:00:03.058213444 814 0x863e30 DEBUG souphttpsrc gstsouphttpsrc.c:1882:gst_soup_http_src_unlock_stop:<source> unlock_stop() 0:00:03.058616592 814 0x863e30 DEBUG souphttpsrc gstsouphttpsrc.c:1954:gst_soup_http_src_do_seek:<source> do_seek(40-18446744073709551615)
Created attachment 316851 [details] debug_all_5 I am attaching a debug created with the following command: # GST_DEBUG_NO_COLOR=1 GST_DEBUG_FILE=/tmp/debug5 GST_DEBUG="*:5" gst-launch-1.0 --gst-fatal-warnings playbin uri=https://cdn.phoenix.intergi.c om/19850/videos/4357110/video-sd.mp4 Setting pipeline to PAUSED ... Pipeline is PREROLLING ... buffering... 100% (gst-launch-1.0:2336): GStreamer-WARNING **: adding flushing pad 'src_1' to running element 'decodebin0', you need to use gst_pad_set_active(pad,TRUE) before adding it. Trace/breakpoint trap Any idea what is wrong?
I'm able to reproduce warnings randomly like this: gst-launch-1.0 uridecodebin caps="audio/mpeg, mpegversion=(int)4;video/x-h264, stream-format=(string)avc" uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 name=d d. ! fakesink d. ! fakesink Setting pipeline to PAUSED ... Pipeline is PREROLLING ... buffering... 100% (gst-launch-1.0:30139): GStreamer-WARNING **: adding flushing pad 'src_0' to running element 'decodebin0', you need to use gst_pad_set_active(pad,TRUE) before adding it. Prerolled, waiting for buffering to finish... Pipeline is PREROLLED ... Setting pipeline to PLAYING ... New clock: GstSystemClock But at least in this case buffers flow to fakesinks, when dvbmediasink is in use we are stuck.
What would be interesting is a stack trace from gdb where the warning originates from. Could you do: $ G_DEBUG=fatal_warnings gdb --args gst-launch-1.0 ... (gdb) run ... wait for warning, it should abort ... (gdb) thread apply all bt ... paste or attach output ... (gdb) kill (gdb) quit
Created attachment 316869 [details] gdb output G_DEBUG=fatal_warnings gdb --args gst-launch-1.0 uridecodebin caps="audio/mpeg, mpegversion=(int)4;video/x-h264, stream-format=(string)avc" uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 name=d d. ! fakesink d. ! fakesink
Created attachment 316870 [details] gdb output correct Oops, sorry mistake, second one is correct
For some reason qtdemux is doing a flushing seek here before decodebin exposes the pad, which makes the decodepad flushing. And then results in the warning. Why is gst_element_add_pad() checking for a flushing pad? Shouldn't it just check for an activated pad instead, i.e. GST_PAD_IS_ACTIVE()?
Created attachment 316873 [details] [review] element: Check for an activated pad before adding, not a non-flushing one The pad could be activated but flushing because of a FLUSH_START event. That's not what we're looking for here, we want to check for activated pads.
Now the big question is: does this help for your case (it shouldn't make a difference)? The other question is why qtdemux is seeking here at all and letting FLUSH_START go up to its srcpads. That seems like a bug too.
Created attachment 316875 [details] gdb dvbmediasink when stuck After applying patch above, there is no Warning anymore, however as you are saying there is no improvement, we are still stuck. In attachment is gdb output on customized dvbmediasink(dumps buffers to files instead of writing them to device), when we are stuck. gdb --arg gst-launch-1.0 playbin uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 video-sink=dvbvideosink audio-sink=dvbaudiosink
Comment on attachment 316873 [details] [review] element: Check for an activated pad before adding, not a non-flushing one Attachment 316873 [details] pushed as c247117 - element: Check for an activated pad before adding, not a non-flushing one
Would be good to know which pad that is that is waiting in a blocking pad probe. In thread 7. Not sure how your custom sinks could cause this to happen unless they use pad probes somewhere.
Can you get a new log with GST_DEBUG=6 after the fix to the assertion?
Created attachment 316883 [details] [review] element: Check for an activated pad before adding, not a non-flushing one The pad could be activated but flushing because of a FLUSH_START event. That's not what we're looking for here, we want to check for activated pads.
Created attachment 316889 [details] debug_6_all_after_patch GST_DEBUG_FILE=debug_6_all_after_patch.log GST_DEBUG_NO_COLOR=1 GST_DEBUG=6 gst-launch-1.0 playbin uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 video-sink=dvbvideosink audio-sink=dvbaudiosink It was stuck, so I killed it in 45 second.
Somehow some events flos is happening from the queue2 src task function and it deadlocks. Trying to figure out why it goes directly through multiqueue
(In reply to Thiago Sousa Santos from comment #21) > Somehow some events flos is happening from the queue2 src task function and > it deadlocks. Trying to figure out why it goes directly through multiqueue Seems like this is the expected behavior. I just noticed these dvbmediasink elements receive non-raw data so there are no decoders or parsers in decodebin. Could be the reason we only see the bug with them.
Some notes on what is happening: 1) playsink blocks all pads until all of them have data 2) dvbmediasink elements accept non-raw data so decodebin never needs decoders or parsers in this scenario 3) flush-stop triggers resending of sticky events (stream-start is resent) 4) This sample file has mdat|moov (in this order) so qtdemux does seeks to read the moov before getting to the mdat 5) flush-stop handling in queues is synchronous (happens on upstream thread) When you use sinks that accept raw data it will have decoders and parsers that need some data before they push caps and buffers. So decodebin won't expose pads until some data actually flows. In this case, qtdemux can do its seeks "safely" as all the events are confined to decodebin's internals. When using dvbmediasink elements as sinks they take non-raw data and qtdemux's pads are exposed directly from decodebin and it is linked to downstream. This makes the flush-stop from qtdemux's seek travel until playsink where the handling makes a stream-start reach the playsink pad block and stalls as everything is happening from a single thread. Still thinking on how to fix this, other than having qtdemux not allow its seek's flush travel downstream.
With my very last build off gstreamer head gstreamer SRCREV = "b427997119a2b6aacbeb550f729936f8b963e24b" gst-libav SRCREV = "029ac8cdd0a9b7c97ab3a7d7b99fe40609e58f1b" gst-plugins-bad SRCREV = "39aa2aaa396b60a9f44bb11e8f1152e1a43f633b" gst-plugins-base SRCREV = "5e55968546a42d8d8468a35d034e097128591a33" gst-plugins-good SRCREV = "e4b2360e6e5bff335a6b688a03a2385bcb8ea9c0" gst-plugins-ugly SRCREV = "15f4be2e44279233e0fc4e3b11c03706e242d83b" The Warning GStreamer-WARNING **: adding flushing pad 'src_0' to running element 'decodebin0', you need to use gst_pad_set_active(pad,TRUE) before adding it Does not show up anymore and the media runs fine again.
I can confirm that situation has slightly improved in latest HEAD, i.e. only sometimes we are stuck. To aid testing, here is pipeline which can be used to reproduce problem without need of dvbmediasinks elements: gst-launch-1.0 playbin uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 video-sink="bin. ( capsfilter caps=video/x-h264 ! fakesink )" audio-sink="bin. ( capsfilter caps=audio/mpeg ! fakesink )" After reverting http://cgit.freedesktop.org/gstreamer/gst-plugins-good/commit/?id=142d8e2d23e5602e7382977af1043d621625f8c8, above pipeline is never stuck anymore.
Yes indeed some media still was not ok after all. After that the revert patch described above is applied all media mp4 is back ok 100 % like before.
Does it work with latest master? It seems to do for me. However I'm still puzzled because when investigated it seemed like it shouldn't work. For example: gst-launch-1.0 playbin uri=https://cdn.phoenix.intergi.com/19850/videos/4357110/video-sd.mp4 video-sink="( capsfilter caps=video/x-h264 ! fakesink async=true sync=true )" audio-sink="( capsfilter caps=audio/mpeg ! fakesink async=true sync=true )" still gets stuck for me
No, we are it's still stuck in: gstreamer SRCREV = "86cc8f0091a40807ef488ae676ce0ff8abe7d072" gst-plugins-bad SRCREV = "f9464ce3549c2b3948a582464631ba4f8dd0d5e7" gst-plugins-base SRCREV = "023af2d3b192f8ebf1bd4fe75a22a4adaedc1e05" gst-plugins-good SRCREV = "4718870959b1bd31633f64934d0f679a3c99d18b" gst-plugins-ugly SRCREV = "c589c6db058d257a32ba51b27a48920f4d185876"
IMHO these flush events should never make it out of qtdemux.
Created attachment 317731 [details] [review] qtdemux: drop flushes from our own offset seek Yes, this patch makes qtdemux drop those flushes. @reporter, can you test it, please? Also, please test if flush seeks work during playback. This just prevents the downstream deadlock from happening. Do we need to fix decodebin as well? Seems like an unusual scenario to have those flushes before streaming happens.
I can confirm that after this patch, we are not stuck anymore. Flush seeks during playback works too. Thank you
Thanks for confirming. commit 0906d822ad3661ad78376494e2d5680a795ff1c6 Author: Thiago Santos <thiagoss@osg.samsung.com> Date: Mon Dec 21 09:57:33 2015 -0300 qtdemux: drop flushes from our own offset seek Prevents downstream from receiving flushes for a seek only in upstream. Those seeks are only to start reading from the right offset when skipping or returning to qt atoms. https://bugzilla.gnome.org/show_bug.cgi?id=758928