PlaybackController.seek() stops generating events

[tkem]

Using both Mopidy-Mobile's "track time" slider and something like mpc seek +1:00 seems to stop Mopidy from generating most events, notably track_playback_ended/track_playback_started when switching to a new track. Instead, I see some volume_changed events in MoMo's log, which clearly don't make sense since volume's been untouched:

websocket:outgoingMessage Object { method: "core.playback.play", params: Object, jsonrpc: "2.0", id: 68 } mopidy-mobile.bundle.min.js:155:8
websocket:incomingMessage Object { jsonrpc: "2.0", id: 68, result: null } mopidy-mobile.bundle.min.js:155:8
websocket:incomingMessage Object { volume: 100, event: "volume_changed" } mopidy-mobile.bundle.min.js:155:8
event:volumeChanged Object { volume: 100 }

This seems to affect Mopidy operation until Mopidy gets restarted. I haven't used MoMo's track time control that much, recently, so I can't say when this was introduced. However, being able to reproduce this with an mpc command seems to indicate a bug in Mopidy, and not the client.

Edit: fixed expected events for sending playback.play.

[tkem]

Sorry, we're talking 'bout Mopidy v2.0.0, of course.
Reproducable both on Ubuntu 16.04 LTS and Raspbian "Jessie"...

[tkem]

For reference, this is what switching to a new track looks like before running mpc seek:

websocket:outgoingMessage Object { method: "core.playback.play", params: Object, jsonrpc: "2.0", id: 99 } mopidy-mobile.bundle.min.js:147:318
websocket:incomingMessage Object { jsonrpc: "2.0", id: 99, result: null } mopidy-mobile.bundle.min.js:147:318
websocket:incomingMessage Object { volume: 100, event: "volume_changed" } mopidy-mobile.bundle.min.js:147:318
event:volumeChanged Object { volume: 100 } mopidy-mobile.bundle.min.js:147:318
websocket:incomingMessage Object { time_position: 0, tl_track: Object, event: "track_playback_ended" } mopidy-mobile.bundle.min.js:147:318
event:trackPlaybackEnded Object { time_position: 0, tl_track: Object } mopidy-mobile.bundle.min.js:147:318
websocket:incomingMessage Object { old_state: "playing", new_state: "playing", event: "playback_state_changed" } mopidy-mobile.bundle.min.js:147:318
event:playbackStateChanged Object { old_state: "playing", new_state: "playing" } mopidy-mobile.bundle.min.js:147:318
websocket:incomingMessage Object { tl_track: Object, event: "track_playback_started" } mopidy-mobile.bundle.min.js:147:318
event:trackPlaybackStarted Object { tl_track: Object }

For some reason, the volume_changed is also sent here, but other events are as expected.
I noted that other events, like tracklist_changed when adding to the tracklist, are still being delivered to the client. So this seems to effect playback events only.

[tkem]

AFAICS, this is also reproducible with the latest Mopidy develop branch.

[tkem]

Same situation after running Mopidy for a couple of days unattended - no more events delivered to MoMo. Restarting Mopidy fixed that. Sorry, not too much information in this (except it may not only be related to seek)...

[ismailof]

For the record I've experienced the same behavour (on Mopidy 2.0 release) but only when using dleyna / podcast backends and after some time. I couldn't reproduce it using mopidy-spotify. I couldn't find a totally reproducible set of steps, so finally I didn't fill an issue.

[tkem]

@ismailof: Thanks for your input! The difference may be that dleyna/podcast rely on the stream backend for "seeking" and actual playback, while mopidy-spotify provides its own implementation, AFAIK. So this may be a stream issue, after all.

[ismailof]

I've been able to test this issue a little bit more, and seems pretty reproductable.

What I'm getting after a seek order :

• the time_position value of the track gets stuck in the new position seeked and won't update anymore
• no new seek, track_playback_ended and track_playback_started are fired from now on
• new tracks starts it the middle of the track as said in mopidy-gmusic issue #114
• everything goes back to normal if I seek to time_position 0

So it seems it has to do with some time_position management after a seek command. I've tested it using mopidy-dylena, but it probably affects others using stream backend too (such as mopidy-podcast or mopidy-gmusic for instance)

Currently I'm using Mopidy release 2.0.0. I'll try to reproduce it with develop branch

[tkem]

Thanks, @ismailof for taking the time to investigate this further!

[adamcik]

5b6632e might be relevant for this, I'll undo the fix to see if I can reproduce.

[adamcik]

Or 3ee9124

[ismailof]

Well, I could do a bit more testing on this, and it led me to the same problem that #1462. If the on_position_change is not well addressed (GStreamer returns position=0 after seek) then _pending_postion never gets cleaned, leading to all the problems described before, since all of them rely on _pending_position not being None.

That said, I could finally test it on a up-to-date develop branch, and it seems that the issue is gone. IMHO #1496 pull request has indeed solved also this issue. But I'm not so confident of my environment so it would be better if @tkem could also confirm that.

I'm attaching the log of a seek order:

2016-07-30 01:02:04,390 DEBUG [1279:HttpServer] mopidy.http.handlers: Received WebSocket message from 192.168.1.21: u'{"id":"core.playback.seek34","jsonrpc":"2.0","method":"core.playback.seek","params":[1472180]}'
2016-07-30 01:02:04,392 DEBUG [1279:Audio-3] mopidy.audio.gst: Sending flushing seek: position=1472180000000L
2016-07-30 01:02:04,396 DEBUG [1279:MainThread] mopidy.audio.gst: Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PAUSED pending=GST_STATE_PAUSED
2016-07-30 01:02:04,403 DEBUG [1279:HttpServer] mopidy.http.handlers: Sent WebSocket message to 192.168.1.21: '{"jsonrpc": "2.0", "id": "core.playback.seek34", "result": true}'
2016-07-30 01:02:04,878 DEBUG [1279:MainThread] mopidy.audio.gst: Got BUFFERING bus message: percent=0%
2016-07-30 01:02:04,884 DEBUG [1279:Dummy-25] mopidy.audio.gst: Got SEGMENT pad event: rate=1.0 format=time start=1472180000000 stop=18446744073709551615 position=0
2016-07-30 01:02:04,886 DEBUG [1279:Dummy-25] mopidy.audio.actor: Audio event: position_changed(position=0L)
2016-07-30 01:02:04,887 DEBUG [1279:Dummy-25] mopidy.listener: Sending position_changed to AudioListener: {'position': 0L}
2016-07-30 01:02:04,891 DEBUG [1279:MainThread] mopidy.audio.gst: Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PAUSED pending=GST_STATE_VOID_PENDING
2016-07-30 01:02:04,892 DEBUG [1279:MainThread] mopidy.audio.actor: Audio event: state_changed(old_state=playing, new_state=paused, target_state=playing)
2016-07-30 01:02:04,893 DEBUG [1279:MainThread] mopidy.listener: Sending state_changed to AudioListener: {'old_state': u'playing', 'target_state': u'playing', 'new_state': u'paused'}
2016-07-30 01:02:04,895 DEBUG [1279:MainThread] mopidy.audio.gst: Got ASYNC_DONE bus message.

2016-07-30 01:02:09,973 DEBUG [1279:MainThread] mopidy.audio.gst: Got BUFFERING bus message: percent=100%
2016-07-30 01:02:09,977 DEBUG [1279:MainThread] mopidy.audio.gst: Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
2016-07-30 01:02:09,978 DEBUG [1279:MainThread] mopidy.audio.actor: Audio event: state_changed(old_state=paused, new_state=playing, target_state=None)
2016-07-30 01:02:09,979 DEBUG [1279:MainThread] mopidy.listener: Sending state_changed to AudioListener: {'old_state': u'paused', 'target_state': None, 'new_state': u'playing'}

[tkem]

@ismailof, @adamcik: Thanks for looking into this! I did some testing with current develop, and to me the issue seems to be resolved, actually. Looking forward to Mopidy v2.0.1 ;-)