Proper EOT / EOS handling #231

Merged
merged 12 commits into from Jan 6, 2013

Conversation

Projects
None yet
2 participants
Owner

adamcik commented Nov 8, 2012

Once completed this will fix: #160, #222, #172, #168, #169. Currently the main issue remaining is how to handle case where we encounter an error and previously would advance to keep playback running. With the EOT handling track changes are async and our old approach is broken.

Owner

adamcik commented Nov 10, 2012

Playing with this, i.e. load spotify playlist, play, seek 95%, observe EOT, seek 95%... I find that sometimes I loose the first 20-30 seconds of an song. I haven't verified yet but i suspect it might be caused by the old appsrc consuming that but being discarded right away.

A quick cross check with playback of local files shows that this is indeed a spotify only issue.

Owner

adamcik commented Nov 11, 2012

I had a theory that this might be caused by music being delivered to the wrong appsrc, so created a quick patch to make the EOT remove the source and new source add it, allowing us to block spotify music delivery. However, this does not seem to fix the issue. Looking at the logs below my new theory is that we should not be delivering anything before the newsegment message is sent out. In other words we probably need a pad probe that waits for this message, and then unblocks delivery.

REMOVING SOURCE
DEBUG    2012-11-11 15:29:46,276 [12889:Dummy-13] mopidy.audio
  Triggering reached end of track event
DEBUG    2012-11-11 15:29:46,290 [12889:PykkaActorThread-5] mopidy.core
  Triggering track playback ended event
DEBUG    2012-11-11 15:29:46,291 [12889:PykkaActorThread-5] mopidy.core
  Triggering track playback started event
0:00:23.457680264 12889  0x9322548 INFO        GST_ELEMENT_PADS gstpad.c:1674:gst_pad_unlink: unlinking playbin2inputselector0:src(0x936fcc0) and playsink0:audio_raw_sink(0x9372088)
0:00:23.457745566 12889  0x9322548 INFO        GST_ELEMENT_PADS gstpad.c:1717:gst_pad_unlink: unlinked playbin2inputselector0:src and playsink0:audio_raw_sink
...
0:00:23.735285737 12889 0xb6100c80 INFO                   pygst gstbuffer.override:69:_wrap_gst_buffer_new: pyo:0xa2befb0 pyr:1 minio:0xaf582c70 minir:1

Edit: removed most of the logs since this was not relevant to the real issues.

Owner

adamcik commented Nov 13, 2012

Turns out I might have to partially fix #191 for this to work. Currently we are outputting gst.Buffers without timestamp or duration set, this seems to confuse gstreamer and/or playbin greatly and gives us the funny behavior with spotify tracks. On a quick side note a similar playback delay can be observed with local songs if you first play a spotify song, end result is jumping about 20-30 seconds into the local track.

But I digress, the solution for all of this seems to tie in with the work I did on #191, i.e. we need to set the appsrc format to time, and annotate buffers with duration and timestamps. I hacked up some code to test with this and I'm no longer able to reproduce the errors I was seeing.

Owner

adamcik commented Nov 14, 2012

Seeing how this is getting all the updates and not the bug I opened I kinda feel silly for opening it at all. Any way, today's new findings: Fist of all, vorbisenc doesn't like it when timestamps get reset between tracks, they must always increase to keep it happy. Secondly the issue with EOT sometimes not working is similar to a race condition. It turns out that the about-to-finish signal is in no way blocking, and if we don't set the url in time we will EOS. This has been confirmed by both adding a sleep(1) to the set uri and by hard coding setting the uri to appsrc:// and via sources on the internet.

There are at least two ways to approach solving this:

  1. Make sure we always manage to set the uri in time. I.e. add a set_next_uri(uri) to audio and make sure to update when ever the playlist or relevant settings change. This way we always have it easily available, this would greatly reduce changes of an EOS, but it's still no guarantee.
  2. Make sure we can recover from when we miss the deadline. One approach to that would to be to store the next url when we try and set it in about-to-finish, missing the deadline is detected by catching the EOS and then using the still set next uri to recover. For this option it is not clear if we can do this in such a way that shout2send etc. never see the EOS.

On a related note I have been using both MP3 and OGG shoutcast streams and the only issue I'm seeing at this point is the EOT race condition. So the uncommitted changes described in in this and previous comments look very promising.

Now, as for getting to this goal I'm planing on taking a step back, setting EOT aside for a little while, taking what I've learned and fixing each of the issues on their own so I can pick this up again with all the foundation work done. Following three changes should probably suffice at this point:

  • Change the audio api to emit_data(buffer) - initially without timestamps/durations
  • Add setting timestamps/durations to spotify backends (consider if setting offset to num samples seen so far is also a good idea)
  • Fix blocking data delivery when we are between sources (not sure if this is really needed, but from a correctness perspective I'm adding it any way).

With these solved I think we would be ready to solve the EOT "race-condition" and fix this :-)

@jodal jodal added a commit that referenced this pull request Nov 16, 2012

@jodal jodal Merge pull request #243 from adamcik/feature/eot-prep-work
Prep work for #231 EOT fixes
6fe6fa4

adamcik added some commits Oct 30, 2012

@adamcik adamcik Detangle EOT and EOS.
This commit tries to detangle EOS from EOT which we have incorrectly
intermingled. EOS events should only be happening at the end of the playlist
when we are about to stop. EOT handling has been removed / broken in this
change, and will need to be re-added with proper tests.
e00b590
@adamcik adamcik Add change track to playback providers.
This method is intended to make implementing EOT handling much more streamlined
by adding a way to easily just change the URI and any other state without
messing with gstreamer pipe states

Naming of this is a bit unfortunate as it is not the same as the
core.playback's concept of change_track. At least not yet
3a9ce05
@adamcik adamcik Use source's factory name to determine type.
Checking the URI inside the new-source handler turned out to tickle some issue
that gave us deadlocks. Getting the source and checking which factory created
it is much safer.
2a391f2
@adamcik adamcik Setup about to finish handling for proper EOT support.
With this change we ask the core.playback system to set the next tracks uri and
otherwise update state as needed. With this change we should be able to support
streaming oggs and gapless playback to mention a few of items this fixes.

On the down side, this change breaks test_end_of_track_skips_to_next_track_on_failure
as there is no clean way to handle this with the async nature of this EOT
handling.
1f54403
@adamcik adamcik Merge branch 'develop' into feature/end-of-track
Conflicts:
	mopidy/audio/actor.py
	mopidy/backends/spotify/playback.py
b78d5ed
@adamcik adamcik Use blocking calls when changing tracks on EOT.
This ensures that we block about-to-finish and the pipeline until the next URI
is set, alowing for at least EOS free playback. If the uri is set quickly enough
this will also be gapless.
39580e1
@adamcik adamcik audio: Handle about to finish for non appsrc playback
The appsrc cleanup code was still short circuiting the about to finish handler,
this meant that EOT handling never happened for local files and playback stopped.

With this change proper EOT handling works for all track types.
81b6620
Owner

adamcik commented Jan 5, 2013

The need for set next uri types of solutions turns out the be completely false. A single missing .get() was the cause of the about to finish handling not blocking as it should. With this mistake fixed we can easily block the pipeline while we wait for the next URI to be set.

With this and a related change that fixes EOT for non appsrc files we are almost done fixing EOT handling. Things that remain are:

  • test_end_of_track_skips_to_next_track_on_failure test failure. For this I think @jodal's opinion is that we should preserve this behavior, i.e. fix the code so the test passes. From my point of view, aiming for EOS-less playback this is a bit tricky, but probably doable if we cobble together the right gstreamer tricks.
  • Testing the issues mentioned in this pull request to see we are not missing anything
Owner

adamcik commented Jan 5, 2013

However, for the last broken test case I think I would prefer to break it and open a new issue to fix the regression of the error handling instead of further blocking this.

@adamcik adamcik Merge branch 'develop' into feature/end-of-track
Conflicts:
	mopidy/audio/actor.py
	mopidy/backends/spotify/playback.py
6d1f84a
Owner

jodal commented Jan 5, 2013

Agree. I think it's more important to get this merged.

I also think pause-on-failure is less important now when GStreamer tracks Spotify track's time position. If Spotify stops delivering data, the GStreamer time position will stall. The only thing missing is changing the state to paused.

Owner

jodal commented Jan 5, 2013

Hum, hum... what about something like this for solving pause-on-failure:

  1. Failure happens, Spotify backend stops pushing data (done)
  2. GStreamers buffer goes empty, time position stops increasing (done)
  3. In addition, when the buffer goes empty, we listen to the buffer message, and change the state to paused
  4. Core mirrors the state of audio (see #234)
  5. Profit!

In other words, we may just need to file an issue for point 3, and not for reintroducing pause-on-failure.

Owner

adamcik commented Jan 5, 2013

Sounds reasonable, but don't forget there could also be playback errors from bad file or stream uris, not just spotify.

Owner

jodal commented Jan 5, 2013

I'd guess that playbin2 pauses or stops the playback state in such cases?

Owner

adamcik commented Jan 5, 2013

With our current code we would get a error message to the message handler which calls stop playback. But in general getting a fatal error will end up tearing down the playbin to a state where automatic state tracking would consider it stopped (if memory serves).

Owner

adamcik commented Jan 5, 2013

We could in theory consider such an error the same as an EOT, and as long as special cases such as loosing the spotify playback token are handled out side of this with and explicit call to pause it might very well work :-)

@jodal jodal and 1 other commented on an outdated diff Jan 5, 2013

mopidy/core/playback.py
if self.tl_track_at_eot:
+ self.current_tl_track = self.tl_track_at_eot
@jodal

jodal Jan 5, 2013

Owner

You should trigger the track_playback_ended event before changing the current track. The event trigger uses the current track to include the track that ended in the event. This is used at least by the Last.fm scrobbler.

@adamcik

adamcik Jan 5, 2013

Owner

Done, felt like I should have added a test though.

Owner

adamcik commented Jan 5, 2013

fb8fba2 gets rid of the hackish way of hooking up EOT, can't think of anything more worth fixing at this time.

Owner

adamcik commented Jan 5, 2013

So yeah, that kinda just broke all the tests, guess we put merging this on hold :P

@adamcik adamcik core: Unbreak end of track related tests.
We should only be hooking up end of track when an audio instance is passed in.
Additionally the tracklist tests where wrongly sending in the audio module
instead of the mock audio.Audio instance.
3857eaa

@jodal jodal added a commit that referenced this pull request Jan 6, 2013

@jodal jodal Merge pull request #231 from adamcik/feature/end-of-track
Proper EOT / EOS handling
1cf9826

@jodal jodal merged commit 1cf9826 into mopidy:develop Jan 6, 2013

1 check passed

default The Travis build passed
Details

adamcik deleted the adamcik:feature/end-of-track branch Jan 6, 2013

@jodal jodal added a commit that referenced this pull request Mar 19, 2013

@jodal jodal Revert "Merge pull request #231 from adamcik/feature/end-of-track"
This reverts commit 1cf9826, reversing
changes made to 711dbe8.
02b845b

@jodal jodal added a commit that referenced this pull request Mar 19, 2013

@jodal jodal Revert "Revert "Merge pull request #231 from adamcik/feature/end-of-t…
…rack""

This reverts commit 02b845b.
f2dbf9f

jodal referenced this pull request Mar 19, 2013

Closed

End of track cleanup #346

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment