Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Seeking when stopped does not go into PLAYING state #2005

Open
kingosticks opened this issue Aug 9, 2021 · 3 comments
Open

Seeking when stopped does not go into PLAYING state #2005

kingosticks opened this issue Aug 9, 2021 · 3 comments
Labels
A-core Area: Core layer
Milestone
Next bug fix release

Comments

@kingosticks
Copy link
Member

kingosticks commented Aug 9, 2021 •
edited

Describe the bug
After performing a seek in the STOPPED state, playback starts at the correct place but Mopidy's state is still STOPPED and commands like stop and pause do not work.

How to reproduce

  1. Stop playback
  2. Seek somewhere in the track (File or Spotify backend)
  3. Pause playback

Expected behaviour
Playback should pause.

Environment

  • Raspberry Pi OS Lite
  • Running latest release as a service

Additional context
Log shows GST state changing to PLAYING but Mopidy's state does not i.e. no mopidy.core.playback Changing state: stopped -> playing message.

Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MpdSession-17] mopidy_mpd.session Request from [::1]:41370: seekcur "30"
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Audio-3] mopidy.audio.gst Changing state to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.gst Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Audio-3] mopidy.audio.gst Sending TAG event for track 'spotify:track:5wnITloAfJ33x0m1R0sQwF': 'taglist, artist=(string)"DON\\ BROCO", title=(string)"One\\ True\\ Prince", album=(string)"One\\ True\\ Prince";'
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Audio-3] mopidy.audio.gst Got source-setup signal: element=GstAppSrc
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Audio-3] mopidy.audio.gst Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MpdSession-17] mopidy_mpd.session Response to [::1]:41370: OK
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.gst Got STREAM_START bus message
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.actor Audio event: stream_changed(uri='appsrc://')
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.listener Sending stream_changed to AudioListener: {'uri': 'appsrc://'}
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Audio-3] mopidy.audio.gst Sending flushing seek: position=30000000000
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Dummy-19] mopidy.audio.gst Got SEGMENT pad event: rate=1.0 format=time start=30000000000 stop=18446744073709551615 position=30000000000
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Dummy-19] mopidy.audio.actor Audio event: position_changed(position=30000)
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Dummy-19] mopidy.listener Sending position_changed to AudioListener: {'position': 30000}
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Core-12] mopidy.core.playback Triggering seeked event
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [Core-12] mopidy.listener Sending seeked to CoreListener: {'time_position': 30000}
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MpdFrontend-15] mopidy.listener Sending player to MpdSession: {}
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.gst Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.gst Got ASYNC_DONE bus message.
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.gst Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.audio.actor Audio event: state_changed(old_state=stopped, new_state=playing, target_state=None)
Aug 09 16:16:39 testpi mopidy[18939]: DEBUG    [MainThread] mopidy.listener Sending state_changed to AudioListener: {'old_state': 'stopped', 'new_state': 'playing', 'target_state': None}

Compared to just starting playback (no seek):

Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MpdSession-17] mopidy_mpd.session Request from [::1]:41528: play
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Audio-3] mopidy.audio.gst Changing state to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.gst Got STATE_CHANGED bus message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Audio-3] mopidy.audio.gst Sending TAG event for track 'spotify:track:5wnITloAfJ33x0m1R0sQwF': 'taglist, artist=(string)"DON\\ BROCO", title=(string)"One\\ True\\ Prince", album=(string)"One\\ True\\ Prince";'
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Audio-3] mopidy.audio.gst Got source-setup signal: element=GstAppSrc
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Audio-3] mopidy.audio.gst Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MpdSession-17] mopidy_mpd.session Response to [::1]:41528: OK
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.gst Got STREAM_START bus message
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.actor Audio event: stream_changed(uri='appsrc://')
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.listener Sending stream_changed to AudioListener: {'uri': 'appsrc://'}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Core-12] mopidy.core.playback Changing state: stopped -> playing
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Core-12] mopidy.core.playback Triggering playback state change event
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Core-12] mopidy.listener Sending playback_state_changed to CoreListener: {'old_state': 'stopped', 'new_state': 'playing'}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Core-12] mopidy.core.playback Triggering track playback started event
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Core-12] mopidy.listener Sending track_playback_started to CoreListener: {'tl_track': TlTrack(tlid=1, track=Track(album=Album(artists=[Artist(name='DON BROCO', uri='spotify:artist:1aOt6LvXOV6I8dv1A5Diia')], date='2021', name='One True Prince', uri='spotify:album:4PzJRdK8unANl6KqYrFjv1'), artists=[Artist(name='DON BROCO', uri='spotify:artist:1aOt6LvXOV6I8dv1A5Diia')], bitrate=320, date='2021', disc_no=0, length=239000, name='One True Prince', track_no=1, uri='spotify:track:5wnITloAfJ33x0m1R0sQwF'))}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MpdFrontend-15] mopidy.listener Sending player to MpdSession: {}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Dummy-19] mopidy.audio.gst Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Dummy-19] mopidy.audio.actor Audio event: position_changed(position=0)
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [Dummy-19] mopidy.listener Sending position_changed to AudioListener: {'position': 0}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.gst Got TAG bus message: tags={'artist': ['DON BROCO'], 'title': ['One True Prince'], 'album': ['One True Prince']}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.actor Audio event: tags_changed(tags=['artist', 'title', 'album'])
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.listener Sending tags_changed to AudioListener: {'tags': ['artist', 'title', 'album']}
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.gst Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.gst Got ASYNC_DONE bus message.
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.gst Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.audio.actor Audio event: state_changed(old_state=stopped, new_state=playing, target_state=None)
Aug 09 16:21:32 testpi mopidy[20058]: DEBUG    [MainThread] mopidy.listener Sending state_changed to AudioListener: {'old_state': 'stopped', 'new_state': 'playing', 'target_state': None}

Note, we do not have a test that exercises this.
kingosticks added a commit to kingosticks/mopidy that referenced this issue Aug 9, 2021
@kingosticks
core: Transition to PLAYING state after pending seek (Fixes mopidy#2005)
660a7e6
@kingosticks
Copy link
Member Author

Note, we do not have a test that exercises this.

Ok... it turns out some tests in https://github.com/mopidy/mopidy/blame/develop/tests/core/test_playback.py are not being run because they are in classes named FooTest instead of TestFoo and pytest doesn't find them. Of all the pointless crap flake8 complains about, why does it miss useful stuff like this?

kingosticks added a commit to kingosticks/mopidy that referenced this issue Aug 9, 2021
@kingosticks
core: Transition to PLAYING state after pending seek (Fixes mopidy#2005)
407eef8 
I had to jiggle the order of events coming from DummyAudio to emit
`stream_changed` before `position_changed` to make things work (i.e.
to make it fail without the fix). I think this makes sense and it also
matches what the real Actor does.
@djmattyg007
Copy link
Contributor

For completeness, this problem was first raised here:

https://discourse.mopidy.com/t/playback-stop-doesnt-work-if-playback-seek-is-used/5080/17

@kingosticks kingosticks reopened this Jan 31, 2022
@kingosticks
Copy link
Member Author

I think this issue, or something very much like it, is still present. Possibly related to our attempts to maintain the current state using get_state() but during an async state change that value will be stale.

@kingosticks kingosticks added this to the Next bug fix release milestone Jan 31, 2022
@kingosticks kingosticks added the A-core Area: Core layer label Jan 31, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-core Area: Core layer
Projects
None yet
Milestone
Next bug fix release
Development

No branches or pull requests
2 participants
@djmattyg007 @kingosticks