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.

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

Starting playback fails if uri or context_uri is provided #288

Closed
forslund opened this Issue Feb 19, 2019 · 45 comments

Comments

Projects
None yet
@forslund
Copy link
Contributor

forslund commented Feb 19, 2019

Starting the playback of an album over spotify connect
Endpoint: me/player/play?device_id=d9464366ec73e0eda87dc781314f8f25d1df7469
Data: {'context_uri': 'spotify:album:6eGYLONkDMja0MNtZWnRRB'}

Results in the librespot player debug output:

INFO:librespot_playback::player: Loading track "Intergalactic (In The Style Of Beastie Boys) [Performance Track with Demonstration Vocals]" with Spotify URI "spotify:track:6ZjubGKa55CYxN9a4LlOV1"
INFO:librespot_playback::player: Track "Intergalactic (In The Style Of Beastie Boys) [Performance Track with Demonstration Vocals]" loaded

This is the last track I played on my desktop spotify player

If I try to just start playback
Endpoint me/player/play?device_id=d9464366ec73e0eda87dc781314f8f25d1df7469
Data: {}

Results in no further output but playback of the above loaded track starts.

Update:

Request for single track using normal uris:
Endpoint: me/player/play?device_id=d9464366ec73e0eda87dc781314f8f25d1df7469
Data: {'uris': ['spotify:track:5fpizYGbi5IQoEraj6FP0R']}

This is on HEAD of master d2cadec

@kingosticks

This comment has been minimized.

Copy link
Contributor

kingosticks commented Feb 19, 2019

Last time I looked, librespot didn't support loading things from a context uri (#57). Have you tried passing the individual tracks via the uris parameter instead?

@pizzaboy75

This comment has been minimized.

Copy link

pizzaboy75 commented Feb 19, 2019

I have the same issue since today.

Something changed on spotify's end.
I cannot select any track for playback. Librespot always resumes the last played track.

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 19, 2019

Huh, weird I've been using context_uri's for quite some time. (more than a year)

In any case the uris doesn't work either:
Endpoint: me/player/play?device_id=d9464366ec73e0eda87dc781314f8f25d1df7469
Data: {'uris': ['spotify:track:5fpizYGbi5IQoEraj6FP0R']}

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 19, 2019

Thanks for confirming @pizzaboy75

@forslund forslund changed the title Starting playback fails Starting playback fails if uri or context_uri is provided Feb 19, 2019

@kingosticks

This comment has been minimized.

Copy link
Contributor

kingosticks commented Feb 19, 2019

Maybe a debug log will shed some light on what's go on. You can specify a specific module by setting the RUST_LOG environment variable appropriately.

RUST_LOG=librespot=debug ./target/debug/librespot <your options>
@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 19, 2019

Thanks, sadly atleast to me it yields very little, this is for 'spotify:track:5fpizYGbi5IQoEraj6FP0R':

DEBUG:librespot_playback::player: command=Load(SpotifyId(u128!(305236747088454385942149979846871671391)), false, 0)
INFO:librespot_playback::player: Loading track "Intergalactic (In The Style Of Beastie Boys) [Performance Track with Demonstration Vocals]" with Spotify URI "spotify:track:6ZjubGKa55CYxN9a4LlOV1"
DEBUG:librespot_audio::fetch: Downloading file 0f71ff89bbcc0ee8621e91e2bf178e78090d6d82
DEBUG:librespot_playback::player: Normalisation Data: NormalisationData { track_gain_db: -6.8700027, track_peak: 1.0767901, album_gain_db: -6.8700027, album_peak: 1.0767901 }
DEBUG:librespot_playback::player: Applied normalisation factor: 0.45341915
INFO:librespot_playback::player: Track "Intergalactic (In The Style Of Beastie Boys) [Performance Track with Demonstration Vocals]" loaded
DEBUG:librespot_audio::fetch: File 0f71ff89bbcc0ee8621e91e2bf178e78090d6d82 complete

Seems there is not very much debug! statements when processing the frames recieved. I'll keep digging but other people are more likely to find the reason for this.

To me it seems like the piece of code extracting the new tracks fail to insert anything new and whatever was there previously gets loaded instead.

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 19, 2019

Added some extra debug prints and it seems like MessageType::kMessageTypeLoad that's processed is always the last thing that actually played. But the status is set to kPlayStatusPause so the playback isn't resumed.

@xMordax

This comment has been minimized.

Copy link

xMordax commented Feb 20, 2019

Same Issue here, I cannot change playlists after selecting one song from the playlist....

@pizzaboy75

This comment has been minimized.

Copy link

pizzaboy75 commented Feb 20, 2019

I think this can be resolved if someone translates the changes made here:

librespot-org/librespot-java@c1006ec

to librespot.

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 20, 2019

Hmm, maybe...

I just tried reverting that update. And that still loads the correct uri, it just pauses the playback right after.

Might be something related to that still...

Edit: I tried adding the same check but with the same result as previous. :(

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 20, 2019

Added some more debug prints to get a handle what's happening and it seems the No frame loading the new uri reaches handle_frame

For starting playback of context_uri': 'spotify:artist:67ea9eGLXYMsO2eYQRui3w'

DEBUG:librespot_connect::spirc: 
! Frame: Type kMessageTypeLoad name "" ident webapi-5509ac5c42cc45d7b4625d0b851a0f1e seq 168238835 id 1550651127456

INFO:librespot_connect::spirc: LOAD COMMAND
INFO:librespot_connect::spirc: context_uri spotify:album:5FzonekEV8kmk1lQmBfnzP
INFO:librespot_connect::spirc: track 1: 
INFO:librespot_connect::spirc: Play: false (2)
DEBUG:librespot_playback::player: command=Load(SpotifyId(u128!(306399372293294196397543171698672325764)), false, 15756)
INFO:librespot_playback::player: Loading track "Call The Ships To Port" with Spotify URI "spotify:track:70XOzn4IstIYPGpcgTFJd2"
DEBUG:librespot_audio::fetch: Downloading file b8a7a1d115bfbe44765cca2b1f62cec7b0412508
DEBUG:librespot_playback::player: Normalisation Data: NormalisationData { track_gain_db: -9.410004, track_peak: 1.2033645, album_gain_db: -8.459999, album_peak: 1.249804 }
DEBUG:librespot_playback::player: Applied normalisation factor: 0.33845413
INFO:librespot_playback::player: Track "Call The Ships To Port" loaded
DEBUG:librespot_audio::fetch: File b8a7a1d115bfbe44765cca2b1f62cec7b0412508 complete
@maciekczwa

This comment has been minimized.

Copy link

maciekczwa commented Feb 20, 2019

I have the same - cannot change songs

@aksel

This comment has been minimized.

Copy link

aksel commented Feb 20, 2019

Same here. It loads the track that is currently playing, no matter what track I select.

I also get the following error, though I am unsure if it is reported by librespot or the client I'm using (spotifyd):

Vorbis error: InitialFileHeadersCorrupt

@warro

This comment has been minimized.

Copy link

warro commented Feb 20, 2019

Same problem here.

ofosos pushed a commit to ofosos/librespot that referenced this issue Feb 21, 2019

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 21, 2019

Here's a short comparison with the java version loading sequence

librespot-java:

2019-02-21 21:00:25 INFO  Player:93 -       LOAD
2019-02-21 21:00:25 DEBUG Player:282 - Loading context, uri: spotify:album:7tB40pGzj6Tg0HePj2jWZt

2019-02-21 21:00:28 INFO  Player:93 -       LOAD
2019-02-21 21:00:28 DEBUG Player:282 - Loading context, uri: spotify:artist:03r4iKL2g2442PT9n2UKsx

librespot:

! Frame: Type kMessageTypeLoad name "" ident webapi-5509ac5c42cc45d7b4625d0b851a0f1e seq 296377722 id 1550779568828

INFO:librespot_connect::spirc: Loading...
INFO:librespot_connect::spirc: context_uri spotify:album:7tB40pGzj6Tg0HePj2jWZ

! Frame: Type kMessageTypeLoad name "" ident webapi-5509ac5c42cc45d7b4625d0b851a0f1e seq 296380046 id 1550779570923

INFO:librespot_connect::spirc: Loading...
INFO:librespot_connect::spirc: context_uri spotify:album:7tB40pGzj6Tg0HePj2jWZt

The second frame seems to be new but contains the same context_uri as the first frame.
Any ideas on what more I can do to help debugging this?

@wdehoog

This comment has been minimized.

Copy link

wdehoog commented Feb 21, 2019

Is the java player really working?

Does Librespot send stuff to spotify as well? And can you log it? If every frame sent to spotify contains the same tracks in its State data maybe Librespot sends something that make Spotify prevent sending new context or tracks.

@worleydl

This comment has been minimized.

Copy link

worleydl commented Feb 21, 2019

Is the java player really working?

Yes, librespot-java is functioning as expected. I dug a little last nite and tried incorporating the play-token fix from that project into librespot but no luck so far. I'm not positive it's related but I saw it mentioned here.

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 21, 2019

I tried librespot-java without the pause fix and that still loads the correct playlist/tracks so I'm pretty sure there's something else afoot as well.

I'm going to try adding more debug of what is actually sent back to spotify before the new tracks are received in the two versions, but I'm basically just stumbling blindly here

@worleydl

This comment has been minimized.

Copy link

worleydl commented Feb 21, 2019

When looking at the frames recieved in spirc: The java client is getting a protocol version of 2.0.0, rust is showing 3.0.1

@worleydl

This comment has been minimized.

Copy link

worleydl commented Feb 21, 2019

Removing the 3 from https://github.com/librespot-org/librespot/blob/master/connect/src/spirc.rs#L217 fixes the issue but I don't know if it causes other issues in the app.

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 22, 2019

@worleydl you should make a PR with that change. So far your change is working for me, I'll continue to test during the day.

@devgianlu

This comment has been minimized.

Copy link
Member

devgianlu commented Feb 22, 2019

@worleydl Did you trying using 4 instead of 3? Does the protocol version change?

@pizzaboy75

This comment has been minimized.

Copy link

pizzaboy75 commented Feb 22, 2019

I did a little digging and i found that @plietar changed the Connect mercury URL to/3/with this commit in May 2017:
plietar/librespot@7c237c7

I think this was done in a whole set of fixes for this particular Issue:
plietar/librespot#185

@forslund

This comment has been minimized.

Copy link
Contributor Author

forslund commented Feb 22, 2019

@devgianlu, I tested with 4 instead of 3 and that results in a panic on startup, due to a 404 response.

@ofosos

This comment has been minimized.

Copy link

ofosos commented Feb 22, 2019

Removing /3 works for me.

@sashahilton00

This comment has been minimized.

Copy link
Member

sashahilton00 commented Feb 22, 2019

I personally can't reproduce this, my guess is it's somewhat dependent on client version, or they're rolling out updates. Given that it's a 1 line URL change, and it seems to solve the issue, I would assume that the fix should be fine to implement, given that it's just a resource locator, and doesn't affect any of the actual librespot logic. If someone wants to create a PR with the change, please also include a short comment in the line above to issue #288 so that if problems sub sequently crop up, it's easy to arrive at this issue and we can continue working a fix from there, we'll merge it.

@kingosticks

This comment has been minimized.

Copy link
Contributor

kingosticks commented Feb 22, 2019

@sashahilton00 did you try the fix out on your account that doesn't have the issue? i.e. does it continue to work or does it break it?

@sashahilton00

This comment has been minimized.

Copy link
Member

sashahilton00 commented Feb 22, 2019

@kingosticks

This comment has been minimized.

Copy link
Contributor

kingosticks commented Feb 22, 2019

Ok, great, just checking. (I just found that I don't have this issue either. Good ol' reliable Blighty!)

EDIT: I tell a lie, I do have this issue. I just messed up reproducing it.

@kingosticks

This comment has been minimized.

Copy link
Contributor

kingosticks commented Feb 22, 2019

This does seem to have resolved the issue, however I will just note here that my official desktop client is still happily talking to the original hm://remote/3/user/<username> endpoint. We might need to come back to this.

michaelherger pushed a commit to michaelherger/spotty that referenced this issue Feb 22, 2019

@sashahilton00

This comment has been minimized.

Copy link
Member

sashahilton00 commented Feb 22, 2019

@kingosticks hmmm, we (myself and @ashthespy) were seeing similar behaviour with the dailymixes endpoint, whereby the desktop clients were getting from the endpoint just fine, but any attempt to do so from librespot failed. I think there's some initialisation/authentication that they've started to add to endpoints that we'll need to work on at some point if it becomes more pressing.

@devgianlu

This comment has been minimized.

Copy link
Member

devgianlu commented Feb 22, 2019

I've noticed that, I don't know if it's related. Also that

@kristaps194

This comment has been minimized.

Copy link

kristaps194 commented Feb 22, 2019

Hi! Sorry for the silly question, I'm new to git...
How do I update my Raspotify Librespot with the ommitment of this 3?
I don't see I could remove it from any text file, so I guess I should somehow delete the current install from RPi, compile and install this new one somehow?
I don't expect you walking me completely throught this but at least a link or comment on the right direction would be appreciated :)

@worleydl

This comment has been minimized.

Copy link

worleydl commented Feb 23, 2019

This project contains a docker setup to do cross platform builds. Build for your platform and replace the files in raspotify.

Reference https://github.com/librespot-org/librespot/wiki/Cross-compiling

@peterdk

This comment has been minimized.

Copy link

peterdk commented Feb 23, 2019

Nice, this fixed it for me as well. I couldn't select a new song or playlist, only thing that worked was enabling local playback, select song, then enable raspotify again as output.

@peterdk

This comment has been minimized.

Copy link

peterdk commented Feb 23, 2019

@kristaps194 To compile an updated version of raspotify, refer to the Building the Package Yourself section on https://github.com/dtcooper/raspotify/blob/master/README.md . I just updated my raspotify and it works again.

@kristaps194

This comment has been minimized.

Copy link

kristaps194 commented Feb 24, 2019

@peterdk thank you for your response! Yesterday I cloned the package and tried to "make" it. First time it compiled for ~15 minutes on my RPi 2. It compiled with errors, couldn't connect to alsa web page. In raspotify folder didn't find any deb package.
Today I updated "make" and tried to rebuild the package (w/o deleted previously cloned content). It finished in less than 1 minute with the same error but significantly less logs (~200 lines vs ~20). Tried to install ufw to simply open port 21. Got kicked out from SSH session and manually restarted. After that quite miraculously switching playlists now works. Perhaps Spotify did something on their end because after building the package I didn't try updating either raspotify or librespot.
Anyway - just wanted for you guys to know how it ended :)

@morloy

This comment has been minimized.

Copy link

morloy commented Mar 7, 2019

librespot.zip

Here’s a build of the current librespot for the Raspberry Pi. Tested and working on moOde.

@devgianlu

This comment has been minimized.

Copy link
Member

devgianlu commented Mar 10, 2019

I've did some packet dumping and noticed that the communication style is different for hm://remote/3/user/.../. You don't need to SUB to the uri anymore, instead they use POST for sending and the events are sent with packet type 0xb5.

Here it is the fix for librespot-java. This did not fix anything.

@kingosticks

This comment has been minimized.

Copy link
Contributor

kingosticks commented Mar 10, 2019

Good work!

@devgianlu

This comment has been minimized.

Copy link
Member

devgianlu commented Mar 10, 2019

Just did some extensive testing and it doesn't work. Hopefully I can sort it out easily. I'll be investigating this behavior when I have time.

@ashthespy

This comment has been minimized.

Copy link
Member

ashthespy commented Mar 11, 2019

@devgianlu Dunno if it is of interest - but I recall noticing quite some chatter via the hm://event-service/v1/events endpoint

@devgianlu

This comment has been minimized.

Copy link
Member

devgianlu commented Mar 11, 2019

These seem to be just for collecting analytics data. What I've noticed is that the client receives a load event, but with the old context. The correct context is sent along with a play event.

I desperately need to improve the dissect tool, if someone can help, please contact me on Gitter.

@devgianlu

This comment has been minimized.

Copy link
Member

devgianlu commented Mar 12, 2019

I've started the huge process of reversing the new protocol. Testers are (very) welcome and contributions are appreciated. See librespot-org/librespot-java#54.

@mfeif

This comment has been minimized.

Copy link

mfeif commented Mar 16, 2019

librespot.zip

Here’s a build of the current librespot for the Raspberry Pi. Tested and working on moOde.

@morloy is that all the audio backends? (I need pulseaudio...)

Thanks for sharing!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.