[gst-devel] caps-nego halting state change

[Matthew Romaine]

Hi folks,

	I am having some problems with the flow of state-changes and
caps-negotiations.  After a few days of debugging, I think I understand
the problem but am unsure about how to resolve.  Here is the situation:

I have a top-level thread (since I will be using a gui as well), and
inside this thread I have a bin.  The bin holds:

filesrc -> fixed-caps-definer -> tee -> volume -> filesink

where 'fixed-caps-definer' is a very simple plugin that has the
data-stream information hardcoded (aka caps).

after all elements are created and connected, everything starts off in
the NULL state by default (right?).  When I initiate a state-change of
the main-thread to PLAYING, its children elements must first transition
to the READY state, which happens just fine.  But when the children must
then transition to the PAUSED state, caps-nego is initiated between the
children elements, and because in one case it fails, the whole
transition change fails as well.

I have determined the caps-nego failure to be because an element is not
in the PAUSED state, as per below debug output (full output at bottom of
email):

DEBUG( 2490: 0)gst_pad_try_set_caps_func:1223: parent user0_volume0 of
pad user0_volume0:sink is not paused     <------------------
INFO ( 2490: 0)gst_pad_try_set_caps:1344: tried to set caps on peerpad
user0_volume0:sink but couldn't
INFO ( 2490: 0)gst_pad_try_set_caps_func:1274: got reply REFUSED (-1)
from connect function on pad user0_tee:sink
INFO ( 2490: 0)gst_pad_try_set_caps_func:1284: pad user0_tee:sink
doesn't accept caps
DEBUG( 2490: 0)gst_element_set_state:1935: [user0_tee] have failed
change_state return


at first, I thought there might be a catch-22 -- caps nego succeeds
(among other reasons) when both elements are in the PAUSED (or PLAYING)
state, yet caps-nego doesn't happen until a transition is requested to a
PAUSED (or PLAYING) state.  But it seems this is fine between two
immediate elements.  The problem arises when you have a gsttee
involved.  

My theory is that during caps-nego when changing state from READY to
PAUSED, gsttee causes a return of GST_PAD_CONNECT_DELAYED because the
tee doesn't care what it handles, which then causes the 'previous
element' (in this case fixed-caps-definer) to try and negotiate with
whatever *succeeds* the tee (in this case, the volume element).  But the
volume element has not changed state yet (to PAUSED), and the whole
transition then fails.

Does this make sense to anyone?  Attached is a snippet of debug output
focusing on this transition sequence which then fails (one with escape
chars for color output if you can manage).  If anyone could shed some
light on this, I would be eternally grateful!

Thanks
Matt Romaine
-------------- next part --------------
CHANGING MAIN_THREAD TO PLAYING 


DEBUG( 2685: 0)gst_element_set_state:1904: [mixer_thread] setting state from NULL to PLAYING
DEBUG( 2685: 0)gst_element_set_state:1922: [mixer_thread] intermediate: setting state from NULL to READY
INFO ( 2685: 0)gst_thread_change_state:309: [mixer_thread] sync(2687): changing state from NULL to READY
DEBUG( 2685: 0)gst_thread_change_state:325: [mixer_thread] sync(2687): creating thread "mixer_thread"
DEBUG( 2685: 0)cothread_stackquery:514: have  posix_memalign at 0x40c00000 of size 2097152
DEBUG( 2685: 0)cothread_stackquery:526: Got new cothread stack from 0x40c00000 to 0x40dfffff (size 2097152)
DEBUG( 2685: 0)gst_basic_scheduler_get_preferred_stack:958: getting preferred stack size as 0x40c00000 and 2097152
DEBUG( 2685: 0)gst_thread_change_state:349: pthread attr set stack at 0x40c00000 of size 2097152
DEBUG( 2685: 0)gst_thread_change_state:354: [mixer_thread] sync(2687): going to pthread_create...
DEBUG( 2688: 0)gst_thread_main_loop:530: gst_thread_main_loop started
DEBUG( 2685: 0)gst_thread_change_state:361: [mixer_thread] sync(2687): pthread created
DEBUG( 2685: 0)gst_thread_change_state:364: [mixer_thread] sync(2687): waiting for child thread spinup
DEBUG( 2688: 0)gst_basic_scheduler_setup:949: initializing cothread context
INFO ( 2688: 0)cothread_context_init:81: initializing cothreads
INFO ( 2688: 0)cothread_context_init:104: 0th thread is 0x810d4e0 at sp:0x40dffa87
INFO ( 2688: 0)gst_thread_main_loop:552: [mixer_thread] sync-main(2685): thread is running
INFO ( 2688: 0)gst_bin_change_state:517: [mixer_thread] changing childrens' state from NULL to READY
DEBUG( 2688: 0)gst_element_set_state:1904: [user0_bin] setting state from NULL to READY
INFO ( 2688: 0)gst_bin_change_state:517: [user0_bin] changing childrens' state from NULL to READY
DEBUG( 2688: 0)gst_element_set_state:1904: [user0_fdsrc] setting state from NULL to READY
INFO ( 2688: 0)gst_element_change_state:2057: user0_fdsrc default handler sets state from NULL to READY 258
INFO ( 2688: 0)gst_bin_child_state_change:470: child user0_fdsrc changed state in bin user0_bin from NULL to READY
INFO ( 2688: 0)gst_bin_child_state_change:485: bin user0_bin need state change to PAUSED
DEBUG( 2688: 0)gst_bin_change_state_norecurse:581: [user0_bin] setting bin's own state
INFO ( 2688: 0)gst_element_change_state:2057: user0_bin default handler sets state from NULL to PAUSED 260
INFO ( 2688: 0)gst_bin_child_state_change:470: child user0_bin changed state in bin mixer_thread from NULL to PAUSED
INFO ( 2688: 0)gst_bin_child_state_change:485: bin mixer_thread need state change to PAUSED
DEBUG( 2688: 0)gst_bin_change_state_norecurse:581: [mixer_thread] setting bin's own state
INFO ( 2688: 0)gst_element_change_state:2057: mixer_thread default handler sets state from NULL to PAUSED 260
INFO ( 2688: 0)gst_basic_scheduler_state_transition:1086: parent "mixer_thread" changed state
INFO ( 2688: 0)gst_basic_scheduler_state_transition:1096: no interesting state change, doing nothing
DEBUG( 2688: 0)gst_element_set_state:1904: [identify0] setting state from NULL to READY
INFO ( 2688: 0)gst_element_change_state:2057: identify0 default handler sets state from NULL to READY 258
INFO ( 2688: 0)gst_bin_child_state_change:470: child identify0 changed state in bin user0_bin from NULL to READY
DEBUG( 2688: 0)gst_element_set_state:1904: [user0_tee] setting state from NULL to READY
INFO ( 2688: 0)gst_element_change_state:2057: user0_tee default handler sets state from NULL to READY 258
INFO ( 2688: 0)gst_bin_child_state_change:470: child user0_tee changed state in bin user0_bin from NULL to READY
DEBUG( 2688: 0)gst_element_set_state:1904: [user0_adder] setting state from NULL to READY
INFO ( 2688: 0)gst_element_change_state:2057: user0_adder default handler sets state from NULL to READY 258
INFO ( 2688: 0)gst_bin_child_state_change:470: child user0_adder changed state in bin user0_bin from NULL to READY
DEBUG( 2688: 0)gst_element_set_state:1904: [user0_volume0] setting state from PAUSED to READY
INFO ( 2688: 0)gst_element_change_state:2057: user0_volume0 defa
-------------- next part --------------
A non-text attachment was scrubbed...
Name: transition_debug
Type: application/octet-stream
Size: 7820 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/gstreamer-devel/attachments/20020801/10e68fb4/attachment.obj>