Unable to get client token after control playback using the api.

GiviMAD commented 1 year ago

Hi, I have facing a bug when trying to use the version from the dev branch, this bug is not present on the 0.4.2 version, which is working great for me at the moment :).

I have just tryed this using macOS, but I think the bug is reproducible on other platforms.

The steps to reproduce the bug are the following:

Start a new librespot client.
Play on the client using a Spotify client like the desktop or mobile application, the speaker gets added to my account and play music correctly.
Restart librespot, it reconnect correctly to my account.
Try to start playback using the Web API (example from docs), librespot is unable to get a client token and therefore fails to start the playback.

After taking a look I think that the problem was introduced by this changes https://github.com/librespot-org/librespot/commit/10650712a77c196c1d0fc2c837c82411fd16410c .

What I has discovered after adding some logs is that when I use the api to start the playback a client id that don't match any of the present in the core/src/spclient.rs is used due to this code .

        // Current state of affairs: keymaster ID works on all tested platforms, but may be phased out,
         // so it seems a good idea to mimick the real clients. `self.session().client_id()` returns the
         // ID of the client that last connected, but requesting a client token with this ID only works
         // on macOS and Windows. On Android and iOS we can send a platform-specific client ID and are
         // then presented with a hash cash challenge. On Linux, we have to pass the old keymaster ID.
         // We delegate most of this logic to `SessionConfig`.
         let client_id = match OS {
             "macos" | "windows" => self.session().client_id(),
             _ => SessionConfig::default().client_id,
         };
         client_data.set_client_id(client_id);

My suspicious is, maybe the client id do not have permissions to use the "streaming" scope? I tried to force it to use the KEYMASTER_CLIENT_ID but this do not solve the problem, maybe other places have been changed to relying on data of the last connected device.

I think that the problem will not only affect to the playback initialization but also will make the token renewal fail whenever it is done after librespot has been controlled using the api.

Probably all of this will make more sense to the maintainers, hope some of this helps to find the problem.

roderickvd commented 1 year ago

I think you are on to something with your analysis. I won't have time to look at this anytime soon, but I can look at PRs and offer advice if I have any.

Here I would appreciate it if someone else could do the trial-and-error thing (or actual packet analysis) of swapping in and out parts of that commit and other keymaster changes, to see what triggered this, so we may work on a fix from there.

kingosticks commented 1 year ago

I can't reproduce this. I'm not 100% sure I am doing exactly the same, the above steps are a little vague. A debug log would be useful.

I do see lots of failures to get a client token but that doesn't stop the playback (for me). I don't know the dev code well enough to understand why playback can continue despite this.

[2023-01-16T14:45:26Z INFO  librespot_playback::player] Loading <Cry> with Spotify URI <spotify:track:7wgxq27uOvfydLunYkcmAU>
[2023-01-16T14:45:26Z DEBUG librespot_audio::fetch] Downloading file 97c6f540925c3c9f3736ac85697d8ce815fa8963
[2023-01-16T14:45:26Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-01-16T14:45:26Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-01-16T14:45:26Z WARN  librespot_core::spclient] Unable to get client token. Trying to continue without...
[2023-01-16T14:45:26Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/storage-resolve/files/audio/interactive/97c6f540925c3c9f3736ac85697d8ce815fa8963?product=0&country=GB&salt=1887686800
[2023-01-16T14:45:27Z TRACE librespot_core::cdn_url] Resolved CDN storage: CdnUrl {
        file_id: FileId(
            Ok(
                "97c6f540925c3c9f3736ac85697d8ce815fa8963",
            ),
        ),
        urls: MaybeExpiringUrls(
            [
                MaybeExpiringUrl(
                    "https://audio-ak-spotify-com.akamaized.net/audio/97c6f540925c3c9f3736ac85697d8ce815fa8963?__token__=exp=1673966727~hmac=5aff36d5c40eef5caf23b2b4fad958f52e63438f9cce2b90ba0977985277dc6d",
                    Some(
                        Date(
                            OffsetDateTime {
                                local_datetime: PrimitiveDateTime {
                                    date: Date {
                                        year: 2023,
                                        ordinal: 17,
                                    },
                                    time: Time {
                                        hour: 14,
                                        minute: 40,
                                        second: 27,
                                        nanosecond: 0,
                                    },
                                },
                                offset: UtcOffset {
                                    hours: 0,
                                    minutes: 0,
                                    seconds: 0,
                                },
                            },
                        ),
                    ),
                ),
                MaybeExpiringUrl(
                    "https://audio4-fa.scdn.co/audio/97c6f540925c3c9f3736ac85697d8ce815fa8963?1673966727_seckweH0XuHOMGAyCDKKyvku3SGYMOKK_PwfBh8DZmc=",
                    Some(
                        Date(
                            OffsetDateTime {
                                local_datetime: PrimitiveDateTime {
                                    date: Date {
                                        year: 2023,
                                        ordinal: 17,
                                    },
                                    time: Time {
                                        hour: 14,
                                        minute: 40,
                                        second: 27,
                                        nanosecond: 0,
                                    },
                                },
                                offset: UtcOffset {
                                    hours: 0,
                                    minutes: 0,
                                    seconds: 0,
                                },
                            },
                        ),
                    ),
                ),
            ],
        ),
    }
[2023-01-16T14:45:27Z TRACE librespot_audio::fetch] Streaming from https://audio-ak-spotify-com.akamaized.net/audio/97c6f540925c3c9f3736ac85697d8ce815fa8963?__token__=exp=1673966727~hmac=5aff36d5c40eef5caf23b2b4fad958f52e63438f9cce2b90ba0977985277dc6d
[2023-01-16T14:45:27Z INFO  librespot_connect::spirc] Resolved 50 tracks from <"spotify:album:5ht7ItJgpBH7W6vJ5BqpPr">
[2023-01-16T14:45:27Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-01-16T14:45:27Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-16T14:45:27Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 24 ms
[2023-01-16T14:45:27Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1184 kbps
[2023-01-16T14:45:27Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1302 kbps
[2023-01-16T14:45:27Z INFO  librespot_playback::player] <Cry> (236533 ms) loaded
[2023-01-16T14:45:27Z TRACE librespot_playback::player] == Starting sink ==
[2023-01-16T14:45:27Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay

roderickvd commented 1 year ago

I do see lots of failures to get a client token but that doesn't stop the playback (for me). I don't know the dev code well enough to understand why playback can continue despite this.

The client token is required for only some of the HTTP endpoints. That's why the code is lenient to try anyway if no client token could be gotten.

kingosticks commented 1 year ago

Ah ok! So, a client token (and therefore an access token) isn't actually required for CDN access and for playback itself? Maybe there's hope for #1098 after all...

roderickvd commented 1 year ago

That’s right.

roderickvd commented 1 year ago

To be clear there are two types of tokens: the “keymaster” one (your choice with a hardcoded token or one gotten from the session) and the “spclient” token which is required for some HTTP endpoints, but indeed not the CDN.

librespot-org / librespot

Unable to get client token after control playback using the api. #1099