When starting up pauses every other Spotify client #146

simmel · 2017-06-20T15:35:41Z

When mopidy with mopidy-spotify is started it pauses every other Spotify client (even other mopidy-spotifies) even though mopidy isn't autostarting the music.

kingosticks · 2017-06-20T15:56:59Z

I cannot reproduce this between instances of mopidy-spotify or my Android client. Only actually playing music causes the play token to be lost.

simmel · 2017-06-20T17:49:56Z

Hm, I can't reproduce this as easy as I thought. But it has happened enough times for me to get so annoyed I reported it at least ; ) I'll update when I can reproduce it 100%.

trygveaa · 2017-06-20T18:30:05Z

Does Mopidy start in paused or stopped state when this happens?

kingosticks · 2017-06-20T18:33:40Z

Actually Yeh I forgot about that relatively new queue/state restoring functionality. Are you using that?

simmel · 2017-06-24T07:26:28Z

Mopidy was in paused state.
I don't think I am using any queue restore? You mean that the previously used.

It just happened now:

My kids were listening with the Spotify application on an iOS device
I resumed my laptop from sleep
1. mopidy was already started but was in paused state
2. WiFi reconnects
3. mopidy takes a few minutes to realize that it has been disconnected from Spotify. In the logs I see: INFO Logged in to Spotify in online mode
The iOS device pauses the music
mopidy on my laptop is still quiet and still paused.
I go to the iOS device and see that it displays "Music has been paused because the Spotify account is used on another device" (or whatever the text says).
I play on the iOS device
When I get back to my laptop I see in the mopdiy logs: WARNING Spotify has been paused because your account is being used somewhere else..

I'm now running mopidy with -vv to have more info when it happens again.

kingosticks · 2017-06-24T07:35:06Z

Ahh right so it's because it's paused (rather than stopped) and restoring the connection (rather than starting mopidy). I think this is because to get to the paused state we need to go through the play state. A more verbose log would hopefully confirm that.

simmel · 2017-06-24T08:22:51Z

That didn't say much:

INFO     2017-06-24 10:21:02,611 [11623:SpotifyEventLoop] mopidy_spotify.backend
  Logged in to Spotify in online mode

Gonna run it with three -v.

simmel · 2017-06-24T09:10:58Z

Hopefully this makes more sense to you than me because I don't see anything obvious:

[...]
DEBUG    2017-06-24 11:06:18,180 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,180 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,281 [13986:Dummy-9] spotify.session
  libspotify log message: 09:06:18.281 E [ap:1694] AP Socket Error: Connection reset by peer (104)
DEBUG    2017-06-24 11:06:18,282 [13986:Dummy-9] spotify.session
  libspotify log message: 09:06:18.282 E [ap:3915] Connection error:  101
DEBUG    2017-06-24 11:06:18,282 [13986:Dummy-9] spotify.session
  Notify main thread
DEBUG    2017-06-24 11:06:18,282 [13986:Dummy-9] spotify.session
  libspotify log message: 09:06:18.282 I [ap:1752] Connecting to AP ap.spotify.com:443
DEBUG    2017-06-24 11:06:18,327 [13986:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2017-06-24 11:06:18,328 [13986:SpotifyEventLoop] spotify.eventloop
  Waiting 16.824s for new events
DEBUG    2017-06-24 11:06:18,346 [13986:Dummy-9] spotify.session
  libspotify log message: 09:06:18.346 I [ap:1226] Connected to AP: 104.199.64.206:443
DEBUG    2017-06-24 11:06:18,418 [13986:Dummy-9] spotify.session
  Notify main thread
DEBUG    2017-06-24 11:06:18,419 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,419 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,419 [13986:Dummy-9] spotify.session
  Music delivery of 2048 frames, 0 consumed
DEBUG    2017-06-24 11:06:18,419 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,419 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,420 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,444 [13986:SpotifyEventLoop] spotify.eventloop
  Notification received; processing events
DEBUG    2017-06-24 11:06:18,447 [13986:SpotifyEventLoop] spotify.session
  Credentials blob updated: '[...]'
DEBUG    2017-06-24 11:06:18,447 [13986:SpotifyEventLoop] spotify.session
  Connection state updated
INFO     2017-06-24 11:06:18,447 [13986:SpotifyEventLoop] mopidy_spotify.backend
  Logged in to Spotify in online mode
DEBUG    2017-06-24 11:06:18,448 [13986:SpotifyEventLoop] spotify.eventloop
  Waiting 16.707s for new events
DEBUG    2017-06-24 11:06:18,579 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,579 [13986:Dummy-9] spotify.session
  Audio buffer stats requested, but no listener
DEBUG    2017-06-24 11:06:18,579 [13986:Dummy-9] spotify.session
  Music delivery of 2048 frames, 0 consumed
[...]

Is there any more debug options you can apply other than starting with mopidy -vvv?

simmel · 2017-06-24T09:12:36Z

Also, I can now reproduce this 100%. I think the key is that mopidys Spotify playback must be paused, computer suspended (or really network loss), another Spotify player starts to play and then libspotify must get reset by peer.

adamcik · 2017-06-24T09:36:52Z

I don't think we go through play to get to paused, order is 'NULL -> READY -> PAUSED -> PLAYING' at least on the GStreamer level. Sounds like something I would have had to try and fix for gapless.

I think the key part here is libspotify being in offline mode while paused and us incorrectly handling it coming back.

simmel · 2017-10-09T12:37:59Z

Any news or ideas here?

kingosticks · 2017-10-09T15:49:54Z

I can now reproduce this thanks to your detailed instructions and and I think I know what's going on:

When the user pauses, we set gstreamer paused which stops emitting any more data to the sound device, stops incrementing track position etc - great.
But we fail to actually tell libspotify it's paused so it continues to deliver us data, which will continue to push into the buffer until it's full and Gstreamer's enough-data signal notifies us via our callback. This sets mopidy-spotify's push_audio_data_event flag and stops mopidy-spotify consuming any more data from libspotify's relentless music_delivery calls.
At this point, everything appears paused, but libspotify still thinks it's playing.
If this mopidy-spotify instance (device 1) then goes offline, and you start playing on device 2, when device 1 comes back online libspotify will still think it's playing and therefore grab the play token that device 2 was enjoying.
If you don't let device 1 go offline then everything works as expected. There must be something in libspotify that automatically pauses playback on receiving a play token lost notification. This does make sense since librespot (the reverse engineered Spotify client) has to explicitly do this.

I think we need a SpotifyPlaybackProvider.pause function which does the same as the existing stop function. I don't know what effect (if any) this will have on ensuring we have continued to buffer sufficient data to allow us to instantly resume playback. I would guess that the buffering is so far ahead that it's OK.

simmel · 2018-05-28T11:25:17Z

This is not an acceptable patch @kingosticks
Spotify songs which were in the saved state are now discarded:

kaka:~$ mopidy
INFO     Starting Mopidy 2.1.0
INFO     Loading config from builtin defaults
INFO     Loading config from /Users/simlu/.config/mopidy/mopidy.conf
INFO     Loading config from command line options
INFO     Enabled extensions: spotify, mpd, http, stream, m3u, scrobbler, softwaremixer, file, local, local-sqlite
INFO     Disabled extensions: none
INFO     Starting Mopidy mixer: SoftwareMixer
INFO     Starting Mopidy audio
INFO     Starting Mopidy backends: StreamBackend, M3UBackend, FileBackend, LocalBackend, SpotifyBackend
INFO     Loaded 4512 local tracks using sqlite
INFO     Audio output set to "autoaudiosink"
INFO     Starting Mopidy core
INFO     Logged in to Spotify in offline mode
INFO     Loading state from /Users/simlu/.local/share/mopidy/core/state.json.gz
INFO     Playback of spotify:track:6g1NlCpW7fgqDnWbCCDrHl failed: Session must be logged in and online to load objects: <ConnectionState.OFFLINE: 4>
WARNING  Track is not playable: spotify:track:6g1NlCpW7fgqDnWbCCDrHl
INFO     Starting Mopidy frontends: MpdFrontend, HttpFrontend, ScrobblerFrontend
INFO     MPD server running at [::1]:6600
INFO     HTTP server running at [::ffff:127.0.0.1]:6680
INFO     Starting GLib mainloop
INFO     Logged in to Spotify in online mode
INFO     New MPD connection from [::1]:58387
INFO     Scrobbler connected to Last.fm
^CINFO     Interrupted. Exiting...
INFO     Stopping Mopidy frontends
INFO     Stopping Mopidy core
INFO     Saving state to /Users/simlu/.local/share/mopidy/core/state.json.gz
INFO     Limiting history to 500 tracks
INFO     Stopping Mopidy backends
INFO     Stopping Mopidy audio
INFO     Stopping Mopidy mixer

kingosticks · 2018-05-28T20:57:07Z

My apologies. I must have missed your input on the PR, how can we rectify this?

…

On Mon, 28 May 2018, 12:25 Simon Lundström, ***@***.***> wrote: This is not an acceptable patch @kingosticks <https://github.com/kingosticks> Spotify songs which were in the saved state are now discarded: kaka:~$ mopidy INFO Starting Mopidy 2.1.0 INFO Loading config from builtin defaults INFO Loading config from /Users/simlu/.config/mopidy/mopidy.conf INFO Loading config from command line options INFO Enabled extensions: spotify, mpd, http, stream, m3u, scrobbler, softwaremixer, file, local, local-sqlite INFO Disabled extensions: none INFO Starting Mopidy mixer: SoftwareMixer INFO Starting Mopidy audio INFO Starting Mopidy backends: StreamBackend, M3UBackend, FileBackend, LocalBackend, SpotifyBackend INFO Loaded 4512 local tracks using sqlite INFO Audio output set to "autoaudiosink" INFO Starting Mopidy core INFO Logged in to Spotify in offline mode INFO Loading state from /Users/simlu/.local/share/mopidy/core/state.json.gz INFO Playback of spotify:track:6g1NlCpW7fgqDnWbCCDrHl failed: Session must be logged in and online to load objects: <ConnectionState.OFFLINE: 4> WARNING Track is not playable: spotify:track:6g1NlCpW7fgqDnWbCCDrHl INFO Starting Mopidy frontends: MpdFrontend, HttpFrontend, ScrobblerFrontend INFO MPD server running at [::1]:6600 INFO HTTP server running at [::ffff:127.0.0.1]:6680 INFO Starting GLib mainloop INFO Logged in to Spotify in online mode INFO New MPD connection from [::1]:58387 INFO Scrobbler connected to Last.fm ^CINFO Interrupted. Exiting... INFO Stopping Mopidy frontends INFO Stopping Mopidy core INFO Saving state to /Users/simlu/.local/share/mopidy/core/state.json.gz INFO Limiting history to 500 tracks INFO Stopping Mopidy backends INFO Stopping Mopidy audio INFO Stopping Mopidy mixer — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#146 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA5DqBArGP3TgHO-gyCFlPI_jl-ws9h-ks5t296egaJpZM4N_xOG> .

simmel · 2018-05-29T13:43:15Z

No idea. I think it's very weird that by just applying your patch breaks mopidys state restore.

kingosticks · 2018-05-29T15:54:22Z

I've reproduced this issue both with and without my patch. The patch itself is fine.

Unfortunately I can't say the same about the state restore functionality which looks broken for Spotify tracks. There's a race condition between Spotify being ready ('Logged in to Spotify in online mode') and loading the track during playback state restoration. Your log clearly shows Mopidy trying to load the Spotify track before the Spotify backed was ready. I guess whether or not you'll run into this depends on the network and possibly also if the track has been previously played (it may still be cached and therefore already "loaded").

I don't think we currently have any mechanism which allows slow backends to signal core they are really ready - maybe we should. As an alternative, we could move pyspotify's connection state check into the timeout case so we give it an opportunity to become ready; a bit of a hack. Or maybe have mopidy-spotify's on_change function wait with a timeout on a new SpotifyBackend._is_ready threading Event that gets set by SpotifyBackend.on_logged_in().

simmel · 2018-05-30T07:57:44Z

Uh, my bad. I could reproduce it 100% yesterday but I can't today. There were other issues with Spotify yesterday so let's just blame them? ; P

If I interpret the logs correctly, and I'm sure I don't, Mopidy-Spotify only needs to be loaded and being in offline mode is OK:

INFO     Starting Mopidy core
INFO     Logged in to Spotify in offline mode
INFO     Loading state from /Users/simlu/.local/share/mopidy/core/state.json.gz
[…]
INFO     Logged in to Spotify in online mode

Thanks for the detailed information about the inners of Mopidy-Spotify @kingosticks ! (And for fixing this issue! = )

kingosticks · 2018-05-30T08:03:06Z

No, being logged in but in offline mode is not enough, you must be in online mode to load a track (the error message explicitly says that).

Session must be logged in and online to load objects: <ConnectionState.OFFLINE: 4>

I've not fixed anything here, it's just not a deterministic issue. If Spotify's servers/your network is slow then you are more likely to hit it. I've opened a new issue at #185 to track how we are actually going to fix this.

kingosticks mentioned this issue Oct 10, 2017

Pause spotify playback when Mopidy paused #162

Merged

kingosticks closed this as completed in 68512f6 May 27, 2018

kingosticks mentioned this issue May 29, 2018

Cannot play track when restoring playback state #185

Open

kingosticks added a commit to kingosticks/mopidy-spotify that referenced this issue Aug 18, 2018

Pause spotify playback when Mopidy paused. (Fixes mopidy#146)

fbe1b85

jodal added this to the v4.0 milestone Dec 13, 2019

jodal assigned kingosticks Dec 13, 2019

kingosticks added a commit to kingosticks/mopidy-spotify that referenced this issue Dec 20, 2023

Pause spotify playback when Mopidy paused. (Fixes mopidy#146)

361aac2

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

When starting up pauses every other Spotify client #146

When starting up pauses every other Spotify client #146

simmel commented Jun 20, 2017

kingosticks commented Jun 20, 2017

simmel commented Jun 20, 2017 via email

trygveaa commented Jun 20, 2017

kingosticks commented Jun 20, 2017

simmel commented Jun 24, 2017

kingosticks commented Jun 24, 2017

simmel commented Jun 24, 2017

simmel commented Jun 24, 2017

simmel commented Jun 24, 2017

adamcik commented Jun 24, 2017

simmel commented Oct 9, 2017

kingosticks commented Oct 9, 2017 •

edited

Loading

simmel commented May 28, 2018

kingosticks commented May 28, 2018 via email

simmel commented May 29, 2018

kingosticks commented May 29, 2018 •

edited

Loading

simmel commented May 30, 2018

kingosticks commented May 30, 2018 •

edited

Loading

When starting up pauses every other Spotify client #146

When starting up pauses every other Spotify client #146

Comments

simmel commented Jun 20, 2017

kingosticks commented Jun 20, 2017

simmel commented Jun 20, 2017 via email

trygveaa commented Jun 20, 2017

kingosticks commented Jun 20, 2017

simmel commented Jun 24, 2017

kingosticks commented Jun 24, 2017

simmel commented Jun 24, 2017

simmel commented Jun 24, 2017

simmel commented Jun 24, 2017

adamcik commented Jun 24, 2017

simmel commented Oct 9, 2017

kingosticks commented Oct 9, 2017 • edited Loading

simmel commented May 28, 2018

kingosticks commented May 28, 2018 via email

simmel commented May 29, 2018

kingosticks commented May 29, 2018 • edited Loading

simmel commented May 30, 2018

kingosticks commented May 30, 2018 • edited Loading

kingosticks commented Oct 9, 2017 •

edited

Loading

kingosticks commented May 29, 2018 •

edited

Loading

kingosticks commented May 30, 2018 •

edited

Loading