pipeline state change returns ASYNC but never completes

[Anssi Hannula]

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 :)

-- 
Anssi Hannula