skuethe/MMM-Spotify

Notifications send by API not recognized after time

timbeckss opened this issue · 23 comments

Hello,

I'm using Raspotify on my RaspberryPI which also hosts the MagicMirror software and MMM-RemoteControl, which offers a RESTFUL Api to send Notifications to the Mirror via HTTP-Requests. The notifications get recognized by MMM-Spotify correctly and I can pause, skip, change device etc. The MagicMirror itself is always chooseable as playback device on any client, no problem there.

The problem is: when I don't use the MagicMirror as a playback device for round about 30 minutes it doesn't recognize any notifications from HTTP-Requests anymore. After I manually select the MagicMirror as playback device, all notifications get recognized correctly again.

Do you have any idea what to do about it?

MagicMirror: 2.14.0
MMM-Spotify: 2.0
MMM-RemoteControl: 2.3.2
Raspotify: 0.16.0

Hey there. Thank you for opening this issue.

So just to recap:

  1. You are controlling MMM-Spotify via notifications send by MMM-RemoteControl
  2. If you switch to any playback device other than the raspotify instance and wait for about 30mins you loose the power to control MMM-Spotify via MMM-RemoteControl

Is that right?
Could you please share your MMM-RemoteControl config - at least the part with the Spotify notifications.
Make sure to remove any sensitive information before copy & pasting the config

You got it absolutely right.

I didn't change anything in the in the MMM-RemoteControl module. The module doesn't have a specific configuration for specific modules. The way I use it, it just send a notification to the MagicMirror. The notification could be basicly anything.

For example: I use this HTTP GET to start playback on the MM: 192.XXX.XXX.XXX:8080/api/notification/SPOTIFY_PLAY

Everything after ..../notification/ will be send as a notification. Since I'm quiet new to this, I can't tell you how it's actually done but you could look it up in the MMM-RemoteControl code.

After some time without playback it isn't controlable through MMM-RemoteControl anymore. When this happened I did log the status of raspotify:

pi@MagicMirror:~ $ sudo systemctl status raspotify
● raspotify.service - Raspotify
   Loaded: loaded (/lib/systemd/system/raspotify.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2021-03-17 01:00:35 CET; 2h 49min ago
  Process: 705 ExecStartPre=/bin/mkdir -m 0755 -p /var/cache/raspotify (code=exited, status=0/SUCCESS)
  Process: 708 ExecStartPre=/bin/chown raspotify:raspotify /var/cache/raspotify (code=exited, status=0/SUCCESS)
 Main PID: 709 (librespot)
    Tasks: 3 (limit: 4915)
   CGroup: /system.slice/raspotify.service
           └─709 /usr/bin/librespot --name MagicMirror --device-type speaker --backend alsa --bitrate 320 --disable-audio-cache --enable-volume-normalisation --volume-ctrl linear --initial-volume=50 --username XXXXX  --password XXXXX

Mär 17 01:04:59 MagicMirror librespot[709]: [2021-03-17T00:04:59Z INFO  librespot_playback::player] Loading <My Way> with Spotify URI <spotify:track:77YGCnTBB84rj02rcWFPwH>
Mär 17 01:05:00 MagicMirror librespot[709]: [2021-03-17T00:05:00Z INFO  librespot_playback::player] <My Way> (182500 ms) loaded
Mär 17 03:08:53 MagicMirror librespot[709]: [2021-03-17T02:08:53Z INFO  librespot_playback::player] Loading <My Way> with Spotify URI <spotify:track:77YGCnTBB84rj02rcWFPwH>
Mär 17 03:08:54 MagicMirror librespot[709]: [2021-03-17T02:08:54Z WARN  librespot_playback::player] Player::play called from invalid state
Mär 17 03:08:54 MagicMirror librespot[709]: [2021-03-17T02:08:54Z INFO  librespot_playback::player] <My Way> (182500 ms) loaded
Mär 17 03:09:30 MagicMirror librespot[709]: [2021-03-17T02:09:30Z INFO  librespot_playback::player] Loading <My Way> with Spotify URI <spotify:track:77YGCnTBB84rj02rcWFPwH>
Mär 17 03:09:31 MagicMirror librespot[709]: [2021-03-17T02:09:31Z INFO  librespot_playback::player] <My Way> (182500 ms) loaded
Mär 17 03:13:42 MagicMirror librespot[709]: [2021-03-17T02:13:42Z WARN  libmdns::fsm] dropping truncated packet from 192.XXX.XXX.XXX:5353
Mär 17 03:13:43 MagicMirror librespot[709]: [2021-03-17T02:13:43Z WARN  libmdns::fsm] dropping truncated packet from 192.XXX.XXX.XXX:5353
Mär 17 03:13:45 MagicMirror librespot[709]: [2021-03-17T02:13:45Z WARN  libmdns::fsm] dropping truncated packet from 192.XXX.XXX.XXX:5353

I did the log at 04:20. Sending the notifications doesn't add anything to the log anymore.

When I manually select the MM as playback device in the Spotify app it adds this to the log

Mär 17 04:23:06 MagicMirror librespot[709]: [2021-03-17T03:23:06Z INFO  librespot_core::session] Connecting to AP "gew1-accesspoint-e-jczs.ap.spotify.com:4070"
Mär 17 04:23:06 MagicMirror librespot[709]: [2021-03-17T03:23:06Z INFO  librespot_core::session] Authenticated as "XXXXXXX" !
Mär 17 04:23:06 MagicMirror librespot[709]: [2021-03-17T03:23:06Z INFO  librespot_playback::audio_backend::alsa] Using alsa sink
Mär 17 04:23:06 MagicMirror librespot[709]: [2021-03-17T03:23:06Z INFO  librespot_core::session] Country: "DE"
Mär 17 04:23:06 MagicMirror librespot[709]: [2021-03-17T03:23:06Z INFO  librespot_playback::player] Loading <My Way> with Spotify URI <spotify:track:77YGCnTBB84rj02rcWFPwH>
Mär 17 04:23:06 MagicMirror librespot[709]: [2021-03-17T03:23:06Z INFO  librespot_playback::player] <My Way> (182500 ms) loaded

Controlling Spotify through MMM-RemoteControl now works like a charm again.

Could be a raspotify issue aswell.

I hope this helps.

Thanks for the update.

On first thought, the 30min thing sounds a lot like Spotifys "timeout" value. As there is no "Stop" button in Spotify, if you pause the current song you are playing, it keeps this as an "active song" for some time (30 mins would probably fit here). But this is just a gut feeling. I need to look into further. A good option for me to finally install raspotify and play around with it :)

Just for my understanding (in easy words): The way I understand how MMM-Spotify works is that it sends a command (like "play this song") to the Spotify API which excecutes the command on the device. When the connection to the Spotify API times out the connection has to be reeastablished again. Did I get that right?

Your first guess seems to be true. After I stopped the playback and waited again the log gave me this:

Mär 17 04:34:16 MagicMirror librespot[709]: [2021-03-17T03:34:16Z INFO  librespot_playback::player] <Counting Stars> (161944 ms) loaded
Mär 17 04:39:27 MagicMirror librespot[709]: [2021-03-17T03:39:27Z ERROR librespot_core::session] Os { code: 110, kind: TimedOut, message: "Connection timed out" }
Mär 17 05:13:40 MagicMirror librespot[709]: [2021-03-17T04:13:40Z WARN  libmdns::fsm] dropping truncated packet from 192.XXX.XXX.XXX:5353

I did some testing and find out that the Spotify API isn't reachable at all after the timeout. It doesn't matter what device I want to start playback on or excecute any order I give them through. Once Spotify is "activated" on a device again by manualy selecting it or playing a song, the conncetion of this device to the API is reeastablished and MMM-Spotify can controll it.

Since this problem doesn't only effect the controllability on the PI, I don't think it's a raspotify issue.
And since the HTTP-Requests come through and the notifications get send correctly, I don't think it's a MMM-RemoteControl issue.

So is this a bug or a feautre? Is there anything that can be done about it?

That is helpful, thanks.

So if we look at how MMM-Spotify behaves when only using the modules UI (so no control via outside notifications), you see this timeout "in action":

  1. You start to play a song from any other device and the Spotify logo of MMM-Spotify will disappear and it will show you the current played song
  2. You pause the playback and see that the image of MMM-Spotify is being dimmed. Keep the song paused
  3. After this "Spotify pause timeout" (~30 mins) the Song info from MMM-Spotify is disappearing and the Spotify logo will be shown again. This means that MMM-Spotify has activated a "disconnected" mode, to not stress the Spotify API with requests
  4. You have to start to play a song from any other device to again show a song information on MMM-Spotify, as you can not control it fully from only the UI

Now we need to make sure, that, whatever notification you send to MMM-Spotify, this will do everything in MMM-Spotifys power to get out of that "disconnected" mode :)

As you mentioned, you don't have a config for the MMM-RemoteControl module, but rather call the notifications directly via a list of HTTP requests.
Can you share these? So which notification you send and with what "payload" (if any).
Or is it only this one you mentioned (SPOTIFY_PLAY)?

I tried SPOTIFY_PLAY, SPOTIFY_PAUSE, SPOTIFY_NEXT, SPOTIFY_PREVIOUS and SPOTIFY_TRANSFER with the Payload "MagicMirror" and "MI 9". The request look like this:

  • Without payload: 192.XXX.XXX.XXX:8080/api/notification/SPOTIFY_PLAY
  • With payload: 192.XXX.XXX.XXX:8080/api/notification/SPOTIFY_TRANSFER/MagicMirror

When send I get this answer when they come through correctly:
{"success":true,"notification":"SPOTIFY_TRANSFER","payload":"MagicMirror"}

All requests work perfectly when connected to the API. And I'm quiet sure they also come through when Spotify is "disconnected" but MMM-Spotify doesn't do anything with the received notifications. So it wouldn't matter if they come from MMM-RemoteControl or any other module.

I will have a look at it in the next couple of days, when there is some time. Thanks you for the additional information.

Soo, I just had some time to take a look at this and found something that pretty much helps to describe the source of this problem:

{
  error: {
    status: 404,
     message: 'Player command failed: No active device found',
    reason: 'NO_ACTIVE_DEVICE'
  }
}

This is the direct response from Spotify API after sending it a "play" api command without any more information to it, while Spotify is in "disconnected" mode. So it seems that Spotify is actually removing your "active device" when this timeout value triggers after you paused a song.
In the API documentation we can see that we can pass an optional device id to pass this "play" command to. But we are currently not doing that:

  play(param, cb) {
    this.doRequest("/v1/me/player/play", "PUT", null, param, cb)
  }

where this.doRequest is describing the arguments as follows:

  doRequest(api, type, qsParam, bodyParam, cb)

So to make use of this, we need to change to third parameter (qsParam) to the device ID (instead of null).

Let's summarize:

  • This is not a bug or error that triggers
  • We need to pass Spotify one of our existing device id's if we want to use the "SPOTIFY_PLAY" notification from the "disconnected" mode
  • To do that, we need to give the user some kind of option to define this device ID or have an fallback to use the "last used" device ID

I need to think about a way to make this work which will probably take some time.

Just as a side note:
The correct way to pass a payload to SPOTIFY_PLAY notification is documented in the README.
An example would be:

notification: SPOTIFY_PLAY
payload: {"context_uri": "spotify:playlist:37i9dQZF1DXaTIN6XNquoW"}

@timbeckss Luckily it was not that hard to implement it. I just merged the change into development branch. can you do me a favour and validate that this works?

This change respects backwards compatibility, so it will not break any current implementations by other users.
The "downside" from this implementation is, that you have to define a default device in your config. This will be the fallback device if Spotify does not have an active device on your account.

To test this, just execute the following commands in the MMM-Spotify modules folder:

git fetch
git checkout development
git pull

Then modify your config with the new setting and your desired default device name and restart MM².

First of all: thank you for your work and quick responses!

  1. A good thing: using the SPOTIFY_PLAY comand seems to reach the Spotify API

  2. When SPOTIFY_PLAY is send without a payloud the log gives me this error:

[26.03.2021 16:02.14.649] [LOG]   [SPOTIFY] There was a problem during playback
[26.03.2021 16:02.14.650] [LOG]   [SPOTIFY] API response: {
  error: {
    status: 403,
    message: 'Player command failed: Restriction violated',
    reason: 'UNKNOWN'
  }

In the Spotify Desktop App I can see that the default device I configurated in the config.txt is now the current playback device, but the last song that was played isn't acticvated anymore so there is currently no playing song.

Screenshot 2021-03-26 160907

I get the same error everytime I use the SPOTIFY_PLAY notification, with or without payload.

When I now close MM², change the defaultDevice to another device, restart the MM² and try SPOTIFY_PLAY again, I get the same error but the playback device doesn't change anymore, no matter what the defaultDevice is.
After I manually select the song on a device, the device is controllabale through notifications again. Same procedure as mentioned in previous posts.

Other notifications than SPOTIFY_PLAY (like SPOTIFY_TRANSFER) don't do anything either. I see that you implemented the SPOTIFY_PLAY notification for this feature. I think using SPOTIFY_TRANSFER and the payload of the device would make the defaultDevice variable unnecessary but that is just a thought. Probably you didn't do it because of the backwards compatibility you mentioned.

Let me know if you need any additional information.

So after reading through your post and having another look at the Spotify API documentation, some feedback:

  1. When SPOTIFY_PLAY is send without a payloud the log gives me this error:
[26.03.2021 16:02.14.649] [LOG]   [SPOTIFY] There was a problem during playback
[26.03.2021 16:02.14.650] [LOG]   [SPOTIFY] API response: {
  error: {
    status: 403,
    message: 'Player command failed: Restriction violated',
    reason: 'UNKNOWN'
  }

Are you using a non-premium account in Spotify?
Because the API definition is mentioning the following about status code 403:

If the user making the request is non-premium, a 403 FORBIDDEN response code will be returned.

This is the case for both, the "play" api call and the "transfer" api call.
Both seem to only work when having a premium account.

When I now close MM², change the defaultDevice to another device, restart the MM² and try SPOTIFY_PLAY again, I get the same error but the playback device doesn't change anymore, no matter what the defaultDevice is.

My first thought on this is, you probably haven't waited for ~30 mins?
The SPOTIFY_PLAY notification only tries to change to the default device if you currently have no active device from Spotify side! I explicitly check against the return code (NO_ACTIVE_DEVICE) from Spotify API here

Other notifications than SPOTIFY_PLAY (like SPOTIFY_TRANSFER) don't do anything either. I see that you implemented the SPOTIFY_PLAY notification for this feature.

As mentioned, both only work with Spotify premium.

I think using SPOTIFY_TRANSFER and the payload of the device would make the defaultDevice variable unnecessary but that is just a thought. Probably you didn't do it because of the backwards compatibility you mentioned.

Yes, using SPOTIFY_TRANSFER before SPOTIFY_PLAY could make this new config setting obsolete. In fact, I am calling the same function behind SPOTIFY_TRANSFER also on the SPOTIFY_PLAY notification if there are no active devices.
But I still think it has an positive addition to people who don't want to / or are limited to the notifications they can send.

So, to summarize:
If you DO NOT have a Spotify premium account, than these errors are the result of that. Specific API endpoints can only be used with premium accounts.

If you DO have a Spotify premium account, I've stumbled upon another information here regarding other possible 403 returns:

Note: To determine if you should send controlling commands to a certain device, check the is_restricted flag on a device object. If you receive the 403 FORBIDDEN code back, this means that the currently active device (or targeted device) is not controllable through the Web API.

To validate this you have two quick options:

  1. use the Spotify console to list all your devices, search for your device name and see if the is_restricted flag is set to true
  2. click the "change devices" button in MMM-Spotify - here you will not see devices which have the is_restricted flag set to true - so if your device name is missing, it seems to be the case

Hope that helps, waiting for your feedback.

Sorry for the late reply!

So first thing: I am a premium member and always have been.

The SPOTIFY_PLAY notification only tries to change to the default device if you currently have no active device from Spotify side! I explicitly check against the return code (NO_ACTIVE_DEVICE) from Spotify API here

I get it now. But I did wait more than 2 hours and didn't have an active playback device. It still gave me the results I mentioned.

To validate this you have two quick options:
use the Spotify console to list all your devices, search for your device name and see if the is_restricted flag is set to true

So I did that and discovered that I just had two available devices. But both aren't restricted. Clicking on "change device" button I had 3 more devices.

{
  "devices": [
    {
      "id": "8bce29f8a13f5561bfb895ef70ffca845f1bb609",
      "is_active": false,
      "is_private_session": false,
      "is_restricted": false,
      "name": "TIMO-DESKTOP",
      "type": "Computer",
      "volume_percent": 100
    },
    {
      "id": "8f0e4654a8df1b6b66a74aac613ba53f5ea2d4c8",
      "is_active": false,
      "is_private_session": false,
      "is_restricted": false,
      "name": "Anna's Wohnung",
      "type": "Speaker",
      "volume_percent": 12
    }
  ]
}

Then I manually selected my MagicMirror as a playback device and ran the command again. It got added to the available devices.

  {
      "id": "3afd1025a34f574546983e066665b18396bf127b",
      "is_active": true,
      "is_private_session": false,
      "is_restricted": false,
      "name": "MagicMirror",
      "type": "Speaker",
      "volume_percent": 9
    },

The time the device pop up there they are controllable through the api.

It must be possible to reach these devices when they are no active available because manually selecting them in the app doesn't do anything different then sending requests to the api or do I get this wrong?
I would love to contribute more to this myself but my skills are quiet limited in this matter and I surely don't know any Java.

Interesting. I have a feeling what could cause this. After installing raspotify myself I stumbled upon this configuration setting which maybe has something todo with being able to control the device from everywhere, when ever you want:

In /etc/default/raspotify:

# To make your device visible on Spotify Connect across the Internet add your
# username and password which can be set via "Set device password", on your
# account settings, use `--username` and `--password`.
#
# To choose a different output device (ie a USB audio dongle or HDMI audio out),
# use `--device` with something like `--device hw:0,1`. Your mileage may vary.
#
#OPTIONS="--username <USERNAME> --password <PASSWORD>"

Do you have this configured? Maybe try if it then behaves differently. *thumbs are pressed*

I thought about this too but I have configurated it. Other devices, like my phone, behave the same way.

After about 45 minutes the devices don't show up anymore when the Spotify console comand is used.

To summarize:

  1. All devices I have are chooseable anytime through the Spotify Desktop or mobile App.
  2. The devices that are not used as a playback device for some time aren't recognized as available devices by the spotify api (using the Spotify console request).
  3. Same thing for MMM-Spotify since it gets the information from the Spotify api.

PS: Looking at this https://community.spotify.com/t5/Spotify-for-Developers/active-a-playback-device-with-API/td-p/4963267 the way you implemented it should work. The documentation mentions the error 403, like you mentioned:

If the user making the request is non-premium, a 403 FORBIDDEN response code will be returned.

How does the communication of MMM-Spotify to the Spotify api work? Is it possible that the comands that are send by MMM-Spotify are considered "non-premium" (because MMM-Spotify doesn't have any account information)?

Hm, and is it just the raspotify device which has this behaviour or also some other playback devices?

Some other experience I ran across when testing multi user setup:

  • Every time I would start playback on one of the network devices with user A, user B would not see this device in the Spotify API list (so also in MMM-Spotify device list)
  • User B however could always see the device in the Spotify desktop app
  • When User B now selected the device which user A started playing on, this device would be popping up back on Spotify API (and of course change playing the music from user B)

So it seems that the desktop app is doing something differently than what is supported by the API?

About your PS:
MMM-Spotify is just taking your auth token and is sending this to Spotify API. It is the same endpoint for every user regardless if they are premium or not.
I really think this 403 error is not because of this non-premium stuff but rather because Spotify has problems locating / activating the device.

Hm, and is it just the raspotify device which has this behaviour or also some other playback devices?

Same for my mobile phone for example.

So it seems that the desktop app is doing something differently than what is supported by the API?

Well then it seems like there is not much we can do? Or do you have any idea?

I really think this 403 error is not because of this non-premium stuff but rather because Spotify has problems locating / activating the device.

It's strange that the device vanish from the list of available devices. Looking at this it seems like this is not a bug: https://developer.spotify.com/documentation/web-api/guides/using-connect-web-api/#devices-not-appearing-on-device-list

Connect Web API relies on local network connections to discover and interact with some devices.
For example, when:
A new device is added to the network
A device is in “sleep” mode
A device on the local network is currently tied to another user account, or
Other reasons specific to the device
As a result, some devices that appear in the Connect picker within the Spotify application may not always be visible or available on the Connect Web API Endpoints.

A device is in “sleep” mode

This explains why I cannot see it when currently not playing.

A device on the local network is currently tied to another user account

This explains the issue in the multi-user setup.

As mentioned in spotify/web-api#671:

The /v1/me/player/devices endpoint will only return information for devices which are both active and controllable.

That does explain a lot. And for stuff like a mobile phone it makes sense, I guess. But shouldn't the raspotify be "always on"?

Seems raspotify only really supports the Spotify Connect client (desktop) where this is not an issue. I've took a quick look at the underlying librespot options, but that also does not look promising to work around this issue.

I am currently somewhat out of ideas. It really does seem this is an ongoing issue with Spotifys Web API - that not all devices are controllable like they are in Spotify Connect.

It really does seem this is an ongoing issue with Spotifys Web API - that not all devices are controllable like they are in Spotify Connect.

Seems to be true. The device with the desktop app (my pc) seems to stay in the list of available devices as long as the app is running. And the echo device in the apartment of my girlfriend which is connected to my Spotify account is always available. So I can control a device in a different city through the API but not my mobile or mirror which are in my local network 😄 So it probably does something different than the other clients. But nevermind.

Thank you very very much for your time. You helped me understand how this works and I learned some things. If you happen to find a solution or workaround at some point let me know. So will I.

Liebe Grüße aus NRW.

Your welcome!
I just added a new label to recognize issues which are the result of the Spotify API restrictions :)
If they update their API someday we can easily identify these issues here.

Grüße aus Hamburch ;)

I've also been running into this issue. I'd love your thoughts on two things:

  1. Any chance you wouldn't mind implementing this on SEARCH / SEARCH_AND_PLAY as well? Currently only supported by PLAY
  2. I've noticed that restarting raspotify seems to get it to appear back on Spotify's API, making it TRANSFERable again. Any chance you could implement a worst case-scenario fail-safe that runs something like: systemctl restart raspotify? I know it's a bit hacky but I think it would work.

Hi @Serkes,

  1. yes, probably. I would need to find some time to make it "nice", so we don't just copy and paste the same code into the searchAndPlay function
  2. First gut feeling is screaming: "no" :) That seems to be a very very very specific hack.

About 2.: if a plain restart from raspotify makes it available again, then maybe raspotify can do something about this issue from their side? Maybe implement a custom config setting which is triggering some "keep alive"? I suggest you open an issue on their repo and ask about this topic.

Hello All ... Did you guys arrive at a solution to the above issue if not I may have the solution?
Be sure to remove the less than greater than symbols < > from the USERNAME and PASSWORD #OPTIONS field:

To make your device visible on Spotify Connect across the Internet add your
username and password which can be set via "Set device password", on your
account settings, use --username and --password.

To choose a different output device (ie a USB audio dongle or HDMI audio out),
use --device with something like --device hw:0,1. Your mileage may vary.

#OPTIONS="--username USERNAME --password PASSWORD"

Please let me know if the above works for any of you - Thanks!