pipeline state change returns ASYNC but never completes

[Anssi Hannula]

On 16.01.2012 21:51, Anssi Hannula wrote:
> On 12.01.2012 20:44, Anssi Hannula wrote:
>> Hi!
>>
>> While debugging some KDE code which uses GStreamer via Phonon, I noticed
>> that when at one point the code asks the pipeline to go from READY to
>> PAUSED, the state change will be performed asynchronously but the
>> transition never completes.
>>
>> Specifically, judging from the debug output it seems the issue happens
>> when gst tries to change the state of "fakesink"
>> (pipeline0->bin0->fakesink0); it returns ASYNC but is never heard from
>> again:
>>
>>> 0:00:05.233369519 16879      0x21c2c00 DEBUG             GST_STATES gstbin.c:2409:gst_bin_change_state_func:<bin0> changing state of children from READY to PAUSED
>>> 0:00:05.233400889 16879      0x21c2c00 DEBUG             GST_STATES gstelement.c:2595:gst_element_set_state_func:<fakesink0> set_state to PAUSED
>>> 0:00:05.233413377 16879      0x21c2c00 DEBUG             GST_STATES gstelement.c:2620:gst_element_set_state_func:<fakesink0> setting target state to PAUSED
>>> 0:00:05.233424935 16879      0x21c2c00 DEBUG             GST_STATES gstelement.c:2633:gst_element_set_state_func:<fakesink0> current READY, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS
>>> 0:00:05.233437822 16879      0x21c2c00 DEBUG             GST_STATES gstelement.c:2667:gst_element_set_state_func:<fakesink0> final: setting state from READY to PAUSED
>>> 0:00:05.233472308 16879      0x21c2c00 DEBUG             GST_STATES gstbin.c:2853:bin_handle_async_start:<bin0> state change busy
>>> 0:00:05.233487226 16879      0x21c2c00 DEBUG             GST_STATES gstbin.c:2853:bin_handle_async_start:<pipeline0> state change busy
>>> 0:00:05.233500219 16879      0x21c2c00 LOG               GST_STATES gstelement.c:2942:gst_element_change_state_func:<fakesink0> default handler tries setting state from READY to PAUSED (0013)
>>> 0:00:05.233523500 16879      0x21c2c00 DEBUG             GST_STATES gstelement.c:2734:gst_element_change_state:<fakesink0> element will change state ASYNC
>>> 0:00:05.233535236 16879      0x21c2c00 LOG               GST_STATES gstelement.c:2774:gst_element_change_state:<fakesink0> exit async state change 2
>>> 0:00:05.233547134 16879      0x21c2c00 DEBUG             GST_STATES gstelement.c:2679:gst_element_set_state_func:<fakesink0> returned ASYNC
>>> 0:00:05.233558708 16879      0x21c2c00 INFO              GST_STATES gstbin.c:2503:gst_bin_change_state_func:<bin0> child 'fakesink0' is changing state asynchronously to PAUSED
>>
>> A full debug log of the session with "*:2,GST_STATES:5" is at:
>> http://onse.fi/files/gst-state-issue.log
>>
>> This is with GStreamer 0.10.35.
>>
>> I gave up debugging the issue further, but I'm posting this here in case
>> someone has seen this before or understands where the issue is.
>> I can provide additional information and/or debug outputs if needed.
>>
>> The above output is with phonon-gstreamer 4.5.1, simply by creating a
>> MediaObject(), sleeping 5 seconds, then setting the PAUSED state, then
>> waiting for another 5 seconds (in which time the transition to PAUSED
>> didn't happen), then doing some other stuff.
> 
> I managed to debug this further and create some self-contained testcases
> (very hacky ones full of copy-paste code...). The issue seems to be that
> 'subtitleoverlay' element "stalls", returning ASYNC but never completing
> the state change READY->PAUSED.
> 
> It looks like that when the pipeline is set like below (only video is
> fed to subtitleoverlay):
>   http://stuff.onse.fi/gst-overlay/out3.png
>   http://stuff.onse.fi/gst-overlay/gsthellofull.c
> the pipeline becomes "stalled" in a state change when one does (like the
> above code) NULL->PAUSED->STOPPED->PAUSED.
> 
> When the pipeline is set so that subtitleoverlay is not connected to
> anything:
>   http://stuff.onse.fi/gst-overlay/out5.png
>   http://stuff.onse.fi/gst-overlay/gsthello.c
> the pipeline becomes "stalled" in a state change immediately on first
> NULL->PAUSED.
> 
> I haven't read gst documentation too much yet, so I'm not sure if the
> latter case or even both are intended behavior.
> 
> I used GST_DEBUG="*:2,GST_STATES:4,subtitleoverlay:5" with the above
> programs to get good debug output.
> 
> I also updated gst to 0.10.32.2 and plugins-base to git 0.10 branch, no
> change in behavior.
> 
> n.b. The testcases above might not exactly match the pipeline images,
> but it shouldn't make any difference.
> 
> I intended to debug this a bit further and refine the testcases and read
> some docs etc, but I'm out of time for now, and since I've made much
> progress from my previous post, I decided to post this status update
> anyway, in case anyone has some idea or knows whether the above results
> are expected :)
> 

I assumed that the latter behavior (unconnected subtitleoverlay) is
expected but the former is not.

I opened a bug report with a patch for further tracking:
https://bugzilla.gnome.org/show_bug.cgi?id=668097

-- 
Anssi Hannula