GNOME Bugzilla – Bug 585268
pipeline: queue EOS message until pipeline reaches PLAYING state
Last modified: 2012-08-14 08:04:45 UTC
Please describe the problem: The test program plays a file with a playbin and two fakesinks inside as audio-sink and video-sink Steps to reproduce: 1. Run the test program Actual results: 15% of the execution, it doesn't go from PAUSED to PLAYING Expected results: It goes to PLAYING and program finishes correctly Does this happen every time? 15% of times Other information:
Created attachment 136217 [details] Test program This test program creates a playbin2 with a fakesink as video-sink and audio-sink. It takes the uri to the media to play.
Created attachment 136218 [details] Media Media that causing the problem. Actually I didn't try with anything else, bug this raises the problem for sure
Created attachment 136221 [details] Script to ease execution in batch The test program captures a signal and aborts. This script runs the program and if it takes more than the TIMEOUT seconds to finish the program, it sends the signal to the program so that the next execution can happen
Created attachment 136222 [details] Test program This is the right test program, the other doesn't use fakesink
Created attachment 136262 [details] Test program I had experienced some problems with receiving EOS before GStreamer informed that we were in PLAYING, so I added some code to detect it. Now program aborts when it receives the timeout signal printing "FAILURE: timeout" and when it gets an EOS without having received the PLAYING signal state change. FYI: I got a 19% of timeout, this is that gstreamer didn't move to PLAYING and 1% of getting EOS before having gone to PLAYING.
Created attachment 136297 [details] Other test program run with: ./gsttest media iterations timeout This program is more similar to the one we use because now we recreate the pipeline but reuse the sinks so in this program we create the pipeline once and set the same fakesink as audio-sink and the same fake sink for video-sink. Apart from the problems that I said, I even experienced problems when changing from NULL to READY, so modified it to check the time it takes to change from one state to other. Percentages are: 0.7% of EOS before getting the PLAYING 11.5% of not transitioning PAUSED->PLAYING Other execution: 0.5% of EOS before getting the PLAYING 22.9% of not transitioning PAUSED->PLAYING As you can see everything is quite random, but you can't trust fakesink for tests in that case.
There is something quite wrong here indeed. For example: it seems that when it fails to transition from PAUSED->PLAYING, _set_state() returns ASYNC, whereas it should return SUCCESS. The EOS failure case would imply that a state-change message got 'lost' somewhere, or there's a race going on where the EOS is posted before the PAUSED->PLAYING state change message. The log points towards the latter: 0:00:00.302314478 29153 0xec1160 gst_bus_post:<bus7> [msg 0xecc6c0] posting on bus, type new-clock, GstMessageNewClock, clock=(GstClock)"\(GstSystemClock\)\ GstSystemClock"; from source <playbin> 0:00:00.308706073 29153 0x10a4640 gst_bus_post:<bus7> [msg 0x10ab710] posting on bus, type eos, (NULL) from source <playbin> 0:00:00.308916574 29153 0xec1160 gst_bus_post:<bus7> [msg 0xf52660] posting on bus, type state-changed, GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from source <playbin>
PS: I was going to say that you should set the "sync" property on the fakesinks to TRUE to avoid this situation, but the issue seems to persist even then.
GstPlaySink is set to PAUSED too late and it races against wavparse, causing a wrong-state.
The EOS before the state-change message can happen and is not considered to be an error. Do you think we should make it so that the state change is before the EOS? (this is not so trivial to do)..
> The EOS before the state-change message can happen and is not considered to be > an error. Do you think we should make it so that the state change is before the > EOS? (this is not so trivial to do).. Hrm, I think so. I find this highly unexpected at least. The order of the async messages should reflect the underlying design rules IMHO (ie. here: eos can only happen in playing state).
(In reply to comment #11) > > The EOS before the state-change message can happen and is not considered to be > > an error. Do you think we should make it so that the state change is before the > > EOS? (this is not so trivial to do).. Problem is that we are using fakesink to mock playback in some tests and in this case, I guess it should never happen that you get EOS before playing anything. > Hrm, I think so. I find this highly unexpected at least. The order of the async > messages should reflect the underlying design rules IMHO (ie. here: eos can > only happen in playing state). Actually, I guess it could if you just seek to the end, but it is not this case.
This fixes the lockups commit c4d729a4daa982386c89200521494a5de6cf2370 Author: Wim Taymans <wim.taymans@collabora.co.uk> Date: Tue Jun 16 18:15:06 2009 +0200 playbin2: set smarter target state on uridecodebin Set the target state of the newly added uridecodebins to somthing else that PAUSED so that we keep their state in sync with the playsink state. Fixes #585268
(In reply to comment #12) > (In reply to comment #11) > > > The EOS before the state-change message can happen and is not considered to be > > > an error. Do you think we should make it so that the state change is before the > > > EOS? (this is not so trivial to do).. > > Problem is that we are using fakesink to mock playback in some tests and in > this case, I guess it should never happen that you get EOS before playing > anything. The reason is that the EOS message is posted by the sink and passed through to the application while the state change message of the pipeline is posted after all elements in the pipeline performed the state change. In this example application, the sink is set to PLAYING first, races to EOS and posts EOS before the pipeline managed to change the state of the other elements and before it managed to post the state change message to PLAYING. One possible solution would be to queue the EOS messages from the sinks and only post them when the pipeline reached PLAYING, after it posted the state change message. This would be the right thing to do, indeed. > > > Hrm, I think so. I find this highly unexpected at least. The order of the async > > messages should reflect the underlying design rules IMHO (ie. here: eos can > > only happen in playing state). > > Actually, I guess it could if you just seek to the end, but it is not this > case. >
So in gst_bin_handle_message_func() we could set a priv->pending_eos=TRUE if GST_STATE(self)!=GST_STATE_PLAYING and in gst_bin_change_state_func() we send the eos when next=GST_STATE_PLAYING and there is a pending_eos?
FWIW, it has been noted that EOS only in PLAYING is stated rather explicitly/publicly, e.g. http://gstreamer.freedesktop.org/data/doc/gstreamer/head/gstreamer/html/GstElement.html#GstStateChange
I *think* this is fixed these days - does anyone know for sure?
Yes, this is fixed by this: commit e22f5d8a68b4a2bfc394d21bb86176feac478c16 Author: Sebastian Dröge <sebastian.droege@collabora.co.uk> Date: Mon Apr 18 14:26:33 2011 +0200 bin: Only post EOS messages after reaching the PLAYING state Fixes bug #647756. *** This bug has been marked as a duplicate of bug 647756 ***