title: GStreamer State Changes
body: <p>Trying to write a player using gstreamer and the playbin element. I'm creating a pipeline, adding a bus watch and waiting for messages on the bus. I then set the uri on the pipeline and wait for it to go to playing state. The code is something like this (checks and cleanup removed):</p>
  
  <pre><code>//when user select a resource
  m_pipeline = gst_element_factory_make("playbin", "playbin0");
  g_object_set(G_OBJECT (m_pipeline), "uri", m_uri.c_str(), NULL);
  gst_element_set_state(m_pipeline, GST_STATE_PAUSED);
  //when user presses 'play'
  gst_element_set_state(m_pipeline, GST_STATE_PLAYING);
  </code></pre>
  
  <p>In my bus callback I then look for GST_MESSAGE_STATE_CHANGED in order to know when the pipeline starts playing. 
  Sometimes this works as expected, I get: NULL->READY, READY->PAUSED, PAUSED->PLAYING.</p>
  
  <p>Sometimes I only get first: NULL->READY. The video starts playing anyway however, so something is working but my application just has no idea that playback has started. </p>
  
  <p>This is just on application startup, so preconditions should be the same for all runs. I'm guessing something is racing, do I need to wait for something before setting states or adding the bus callback maybe? </p>
  
  <p>I am using gstreamer 1.8.1 on windows btw. </p>
  
  <p>These are logs obtained by setting GST_DEBUG to 4. </p>
  
  <p>When I get the state change:</p>
  
  <pre>
  0:00:02.918974302  7028   0DF19EC0 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed: notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 
  0:00:02.919185366  7028   06452D20 FIXME                    bin gstbin.c:4144:gst_bin_query: implement duration caching in GstBin again 
  0:00:02.919405213  7028   06452D20 FIXME                    bin gstbin.c:4144:gst_bin_query: implement duration caching in GstBin again 
  0:00:02.919624475  7028   06452D20 FIXME                    bin gstbin.c:4144:gst_bin_query: implement duration caching in GstBin again 
  0:00:02.919882670  7028   06452D20 FIXME                    bin gstbin.c:4144:gst_bin_query: implement duration caching in GstBin again [Media]             
  IPlayer.cpp:555  gst_element_query_duration 85542000000ns [Media]             
  IPlayer.cpp:152  Pipeline playbin0 changed state from PAUSED to PLAYING pending VOID_PENDING. Duration 85542ms
  0:00:02.926384105  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.927016128  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.927645809  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.929138777  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.929487722  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.929740355  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.931064998  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.931415992  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.932754686  7028   06452D20 INFO              GST_STATES gstbin.c:1915:gst_bin_get_state_func: getting state
  0:00:02.933954622  7028   06452D20 INFO                 default gstdebugutils.c:811:gst_debug_bin_to_dot_file: wrote bin graph to : 'dot\IPlayer-PLAYING.dot'
  0:00:02.950122584  7028   0DEB5920 INFO            videodecoder gstvideodecoder.c:1432:gst_video_decoder_sink_event_default: upstream tags: taglist, video-codec=(string)"H.264\ \(Main\ Profile\)", bitrate=(uint)2981313, minimum-bitrate=(uint)281200, maximum-bitrate=(uint)1461000;
  </pre>
  
  <p>When I don't get the state change:</p>
  
  <pre>
  0:00:02.947089811 11792   0D369EC0 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed: notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 
  0:00:02.981495398 11792   0D307920 INFO            videodecoder gstvideodecoder.c:1432:gst_video_decoder_sink_event_default: upstream tags: taglist, video-codec=(string)"H.264\ \(Main\ Profile\)", bitrate=(uint)2981313, minimum-bitrate=(uint)281200, maximum-bitrate=(uint)1461000; 
  0:00:03.020488493 11792   0D307920 INFO videodecoder gstvideodecoder.c:1432:gst_video_decoder_sink_event_default: upstream tags: taglist, video-codec=(string)"H.264\ \(Main\ Profile\)", bitrate=(uint)2981313, minimum-bitrate=(uint)281200, maximum-bitrate=(uint)3918800;
  </pre>
  
  <p>Of course the logs are a lot longer, but I'm assuming this is the relevant place. The IPlayer.cpp stuff is my application, so this is only when I get the callback. When I add/remove certain printf's I can no longer reproduce the problem, so it seems like some kind of race condition to me. </p>
  
  <p>Edited to add logs as well as reflect what code is executed on which user actions.</p>