MPRIS: Player status indicates spotifyd is "Stopped" even though it is playing

[Grmume]

I'm running spotifyd on Arch Linux using the provided systemd unit (installed using the arch linux package version 0.2.24-2) I have another service which monitors whether any MPRIS compatible player is currently playing media. For that purpose I'm using the playerctl tool. Unfortunately spotifyd sometimes reports "Stopped" or "Paused" even though audio is currently playing. I could not figure out when this happens. Right now the command "playerctl -p spotifyd status" returns "Stopped" consistently even though spotifyd is playing audio at the moment. Pausing or resuming the playback does not change the status. Yesterday spotifyd sometimes reported "Playing" but changed to "Stopped" or "Paused" seemingly at random for about 10s before switching to "Playing" again.

For example here is the output of journalctl --user -u spotifyd. Spotifyd loads the tracks and plays them correctly. Aug 27 12:27:13 nas spotifyd[1445]: Couldn't fetch metadata from spotify: Err(Unauthorized) Aug 27 12:27:13 nas spotifyd[1445]: Couldn't fetch metadata from spotify: Err(Unauthorized) Aug 27 12:27:13 nas spotifyd[1445]: Loading <Miami Showdown> with Spotify URI spotify:track:2DoQOnQ0dPOTSYWhBFMK58 Aug 27 12:27:13 nas spotifyd[1445]: <Miami Showdown> loaded Aug 27 12:27:13 nas spotifyd[1445]: Loading <Fire> with Spotify URI spotify:track:7EZXYslJB5VZUbGma0kt9c Aug 27 12:27:14 nas spotifyd[1445]: <Fire> loaded Aug 27 12:27:15 nas spotifyd[1445]: Loading <Three Day Road> with Spotify URI spotify:track:79hEgvfXVNbYT2AjaJ7ake Aug 27 12:27:16 nas spotifyd[1445]: <Three Day Road> loaded

Still, playerctl reports that spotifyd is "Stopped" (command used: for i in {1..10}; do echo $(date): $(playerctl -p spotifyd status); done) : Thu Aug 27 12:27:11 PM CEST 2020: Stopped Thu Aug 27 12:27:11 PM CEST 2020: Stopped Thu Aug 27 12:27:11 PM CEST 2020: Stopped Thu Aug 27 12:27:11 PM CEST 2020: Stopped Thu Aug 27 12:27:12 PM CEST 2020: Stopped Thu Aug 27 12:27:12 PM CEST 2020: Stopped Thu Aug 27 12:27:12 PM CEST 2020: Stopped Thu Aug 27 12:27:12 PM CEST 2020: Stopped Thu Aug 27 12:27:12 PM CEST 2020: Stopped Thu Aug 27 12:27:13 PM CEST 2020: Stopped

Using dbus-send yields the same result. The following command:

dbus-send --print-reply=literal --session --reply-timeout=100 --dest=org.mpris.MediaPlayer2.spotifyd /org/mpris/MediaPlayer2 org.freedesktop.DBus.Properties.Get string:"org.mpris.MediaPlayer2.Player" string:"PlaybackStatus"

Returns: variant Stopped

even though spotify is playing.

[evrardjp]

Can you check logs in more details ? I have the impression you are hitting rate limiting. See #503 .

[f1u77y]

I can reproduce this issue with custom SPOTIFYD_CLIENT_ID. Logs don't show anything suspicious:

Loading config from "/home/f1u77y/.config/spotifyd/spotifyd.conf"
No password specified. Checking password_cmd
Running "pass show spotify.com/f1u77y | head -1" using "/usr/bin/fish"
No proxy specified
Using software volume controller.
Connecting to AP "gew1-accesspoint-e-cwc3.ap.spotify.com:443"
Authenticated as "(my user id)" !
Country: "RU"
Unhandled DBus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Unhandled DBus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Unhandled DBus message: (MethodCall, Some("/"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect"))
Unhandled DBus message: (MethodCall, Some("/"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect"))
Unhandled DBus message: (MethodCall, Some("/org"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect"))
Unhandled DBus message: (MethodCall, Some("/org"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect"))
Unhandled DBus message: (MethodCall, Some("/org/mpris"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect"))
Unhandled DBus message: (MethodCall, Some("/org/mpris"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect"))

Also, fetching metadata works well, but there's still an issue with it. Some MPRIS widgets (eg. the one in Plasma) rely on org.freedesktop.DBus.Properties.PropertiesChanged, but spotifyd doesn't send it when metadata is updated. That causes such a behaviour: querying the property returns updated metadata, while listening to the object (eg. with gdbus monitor -e -d org.mpris.MediaPlayer2.spotifyd) shows nothing (but it should show PropertiesChanged signals).

I don't know if the bug is on your side or it is on the side of dbus crate, but I'm sure it's not related to rate limit per client.

UPD AFAICU, the second part of the issue was a flaw in dbus crate, which is fixed in 0.6.2. I still cannot understand what causes the original issue (Stopped status).

[Lyndeno]

Also, fetching metadata works well, but there's still an issue with it. Some MPRIS widgets (eg. the one in Plasma) rely on org.freedesktop.DBus.Properties.PropertiesChanged, but spotifyd doesn't send it when metadata is updated. That causes such a behaviour: querying the property returns updated metadata, while listening to the object (eg. with gdbus monitor -e -d org.mpris.MediaPlayer2.spotifyd) shows nothing (but it should show PropertiesChanged signals).

This sounds like the problem I am having, I have a python script that listens for changes in metadata. The script does not update the displayed data when a song changes.

[robinvd]

There is https://github.com/Spotifyd/spotifyd/pull/575

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[flying-sheep]

Please pin this so @stale leaves it alone.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[flying-sheep]

Can this please be pinned to the stale bot doesn’t spam?

[eladyn]

Now that we have #1025 and #1079, can anyone confirm this is still an issue on the current master?

[flying-sheep]

Looks good! I can now see album art and control playback on KDE Plasma through MPRIS. I hope https://github.com/Spotifyd/spotifyd/milestone/11 gets achieved soon for a 0.3.4

The only remaining issue I can see is that the track progress bar doesn’t show the current position, it’s always at the end (0 seconds left in current song playback). But that’s probably #1112

[eladyn]

@flying-sheep The last issue you mention is indeed part of #1112 and addressed in #1113. Would you be able to check if that fixes positions in KDE?