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

error audio key, unable to load key #1236

Closed
fivebanger opened this issue Dec 27, 2023 · 35 comments
Closed

error audio key, unable to load key #1236

fivebanger opened this issue Dec 27, 2023 · 35 comments
Labels

Comments

@fivebanger
Copy link
Contributor

Describe the bug
Librespot cannot play podcast episode. In this particular situation I'm trying to load "spotify:episode:7CDoCFJUAnwOLPVieM1Us0", "Schenken - Die Geschichte des Gebens und Nehmens".
This issue happens with Librespot dev-branch, compiled as --release (librespot 0.5.0-dev 886617e (Built on 2023-12-10, Build ID: 6mScPS9U, Profile: release).
This issue does not happen with Librespot v0.4.2.

To reproduce
Steps to reproduce the behavior:

  1. Start Librespot:$ ./librespot --verbose
  2. Start Podcast spotify:episode:7CDoCFJUAnwOLPVieM1Us0, playing on the mobile.
  3. In the client click on "Connect to 'Librespot'"
  4. See error

Log
[2023-12-27T10:49:23Z TRACE librespot_audio::fetch] Streaming from https://audio-ak-spotify-com.akamaized.net/audio/2916bc99f9878b1197de961a1c15fc572b8086ae?__token__=xxxxxxxxxxxxxxxxxxxxxxxxx
[2023-12-27T10:49:23Z DEBUG librespot::component] new AudioKeyManager
[2023-12-27T10:49:23Z ERROR librespot_core::audio_key] error audio key 0 1
[2023-12-27T10:49:23Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2023-12-27T10:49:23Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 27 ms
[2023-12-27T10:49:23Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1820 kbps
[2023-12-27T10:49:24Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1320 kbps
[2023-12-27T10:49:24Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 20 ms
[2023-12-27T10:49:24Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1653 kbps
[2023-12-27T10:49:24Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1815 kbps

Host (what you are running librespot on):

  • OS: Linux
  • Platform: PC (Linux Mint 20.3 Cinnamon)
  • Mobile: Android
  • Location: Germany

Additional context
As already mentioned, the episode plays fine using Librespot v0.4.2 release. I can provide more detailed log for both, Librespot dev-branch and Librespot v0.4.2, both in verbose mode. But I'm not sure which log-information to delete with respect to personal and sensitive data (like tokens, etc.).

@fivebanger fivebanger added the bug label Dec 27, 2023
@michaelherger
Copy link
Contributor

@roderickvd et al. - I'm still seeing the same, running 0.5.0-dev e24fc72. Some podcasts would no longer play, which would still play using 0.4.2 931b4e6.

I tried to capture a debug log. Maybe it's of some help.

debug.log

@fivebanger
Copy link
Contributor Author

@roderickvd et al. - I'm still seeing the same, running 0.5.0-dev e24fc72. Some podcasts would no longer play, which would still play using 0.4.2 931b4e6.

I tried to capture a debug log. Maybe it's of some help.

debug.log

I can confirm that @michaelherger's example "Heimat und Abschied: Was die Rückkehr auf den Balkan mit Familien macht" does not play using a recent librespot v0.5.0-dev version.

@fivebanger
Copy link
Contributor Author

I have tried to dig a little bit more into that. I have added some debug lines of code inside player.rs, fn load_track() in v0.5.0-dev as well as v0.4.2:

        error!("hmk, line 996: format: {:?}", &format);
        error!("hmk, line 997: spotify_id: {}", &spotify_id);
        error!("hmk, line 998: file_id: {}", &file_id);

I get a different "file_id" depending if I run v0.5.0-dev or v0.4.2, pls. see log:

v0.5.0-dev:
[2024-09-15T20:38:42Z INFO librespot] librespot 0.5.0-dev VERGEN_IDEMPOTENT_OUTPUT (Built on 2024-09-03, Build ID: upyelh1p, Profile: release)
[2024-09-15T20:38:42Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-09-15T20:38:42Z INFO librespot_playback::convert] Converting with ditherer: tpdf
[2024-09-15T20:38:42Z INFO librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2024-09-15T20:38:42Z INFO librespot_playback::audio_backend::rodio] Using audio device: default
[2024-09-15T20:38:51Z INFO librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2024-09-15T20:38:51Z INFO librespot_core::session] Authenticated as "xxx" !
[2024-09-15T20:38:51Z INFO librespot_core::session] Country: "DE"
[2024-09-15T20:38:51Z INFO librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point
[2024-09-15T20:38:52Z INFO librespot_playback::player] Loading <Schenken - Die Geschichte des Gebens und Nehmens> with Spotify URI spotify:episode:7CDoCFJUAnwOLPVieM1Us0
[2024-09-15T20:38:52Z ERROR librespot_playback::player] hmk, line 996: format: OGG_VORBIS_96
[2024-09-15T20:38:52Z ERROR librespot_playback::player] hmk, line 997: spotify_id: spotify:episode:7CDoCFJUAnwOLPVieM1Us0
[2024-09-15T20:38:52Z ERROR librespot_playback::player] hmk, line 998: file_id: 2916bc99f9878b1197de961a1c15fc572b8086ae
[2024-09-15T20:38:52Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-15T20:38:52Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
^C[2024-09-15T20:38:57Z INFO librespot] Gracefully shutting down
[2024-09-15T20:39:05Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: Deadline expired before operation could complete { wait timeout exceeded }

v0.4.2:
[2024-09-15T20:39:17Z INFO librespot] librespot 0.4.2 UNKNOWN (Built on 2024-09-09, Build ID: lIuLog07, Profile: release)
[2024-09-15T20:39:22Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
[2024-09-15T20:39:22Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
[2024-09-15T20:39:22Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2024-09-15T20:39:22Z INFO librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"
[2024-09-15T20:39:23Z INFO librespot_core::session] Authenticated as "xxx" !
[2024-09-15T20:39:23Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-09-15T20:39:23Z INFO librespot_playback::convert] Converting with ditherer: tpdf
[2024-09-15T20:39:23Z INFO librespot_core::session] Country: "DE"
[2024-09-15T20:39:23Z INFO librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2024-09-15T20:39:23Z INFO librespot_playback::audio_backend::rodio] Using audio device: default
[2024-09-15T20:39:24Z INFO librespot_playback::player] Loading <Schenken - Die Geschichte des Gebens und Nehmens> with Spotify URI spotify:episode:7CDoCFJUAnwOLPVieM1Us0
[2024-09-15T20:39:24Z ERROR librespot_playback::player] hmk: format: OGG_VORBIS_96
[2024-09-15T20:39:24Z ERROR librespot_playback::player] hmk: spotify_id: spotify:episode:7CDoCFJUAnwOLPVieM1Us0
[2024-09-15T20:39:24Z ERROR librespot_playback::player] hmk: file_id: 7f92925ea512da09675c5bce2a6a3e7c1e828a94
[2024-09-15T20:39:26Z INFO librespot_playback::player] <Schenken - Die Geschichte des Gebens und Nehmens> (2620995 ms) loaded
^C[2024-09-15T20:39:42Z INFO librespot] Gracefully shutting down

Even though the Spotify-ID is the same, v0.4.2 gives another file-id compared to v0.5.0-dev. Unfortunately I'm not familiar with any inside view of Spotify and librespot, so no idea why the two versions results in different file_ids and if this is the root cause for not playing the episode using v0.5.0-dev.

@SuisChan
Copy link
Contributor

Does this only happen with episodes? I have some thoughts, will look later

@michaelherger
Copy link
Contributor

FWICT yes. In one case it seemed to not even impact all episodes, but only some, probably the most recent ones.

@fivebanger
Copy link
Contributor Author

fivebanger commented Sep 16, 2024

Does this only happen with episodes? I have some thoughts, will look later

While playing around (I thought its maybe related to 96kbps bit-rate) I found that this "error audio key 0 1" appears also for any song I have tried to play when librespot was started with "--bitrate 96". Same as for the episodes: Plays fine with v0.4.2, does not play with v0.5.0-dev.

Steps to reproduce:

  • start librespot with 96kbps: $ ./librespot --bitrate 96
  • connect with Spotify app from mobile phone and start just any song

Log trace for v0.5.0-dev (with additional debug msgs, marked as error):

[2024-09-11T20:05:38Z INFO librespot] librespot 0.5.0-dev VERGEN_IDEMPOTENT_OUTPUT (Built on 2024-09-03, Build ID: upyelh1p, Profile: release)
[2024-09-11T20:05:38Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-09-11T20:05:38Z INFO librespot_playback::convert] Converting with ditherer: tpdf
[2024-09-11T20:05:38Z INFO librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2024-09-11T20:05:38Z INFO librespot_playback::audio_backend::rodio] Using audio device: default
[2024-09-11T20:05:43Z INFO librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2024-09-11T20:05:44Z INFO librespot_core::session] Authenticated as "xxx" !
[2024-09-11T20:05:44Z INFO librespot_core::session] Country: "DE"
[2024-09-11T20:05:44Z INFO librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point
[2024-09-11T20:05:44Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:4vWfES1aalWtGA6cFTiFSw
[2024-09-11T20:05:44Z ERROR librespot_playback::player] hmk: format: OGG_VORBIS_96
[2024-09-11T20:05:44Z ERROR librespot_playback::player] hmk: spotify_id: spotify:track:4vWfES1aalWtGA6cFTiFSw
[2024-09-11T20:05:44Z ERROR librespot_playback::player] hmk: file_id: 6250d957950d2cde266961c870ce6d3868dd2959
[2024-09-11T20:05:44Z ERROR librespot_connect::spirc] ContextError: Error { kind: Unknown, error: StatusCode(502) }
[2024-09-11T20:05:44Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-11T20:05:44Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2024-09-11T20:05:47Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2024-09-11T20:05:47Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4vWfES1aalWtGA6cFTiFSw")>: ()
[2024-09-11T20:05:47Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:5TTcVHPZVETHYLXXqCXsRN
[2024-09-11T20:05:47Z ERROR librespot_playback::player] hmk: format: OGG_VORBIS_96
[2024-09-11T20:05:47Z ERROR librespot_playback::player] hmk: spotify_id: spotify:track:5TTcVHPZVETHYLXXqCXsRN
[2024-09-11T20:05:47Z ERROR librespot_playback::player] hmk: file_id: 0587a52e29ae9e736300beeeb2686256da90ba56
[2024-09-11T20:05:47Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-11T20:05:47Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2024-09-11T20:05:48Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
^C[2024-09-11T20:05:52Z INFO librespot] Gracefully shutting down

Log for v40.4.2 (with additional debug msgs, marked as error):

[2024-09-11T20:06:40Z INFO librespot] librespot 0.4.2 UNKNOWN (Built on 2024-09-09, Build ID: lIuLog07, Profile: release)
[2024-09-11T20:06:47Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
[2024-09-11T20:06:47Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
[2024-09-11T20:06:47Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2024-09-11T20:06:47Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443
[2024-09-11T20:06:47Z INFO librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"
[2024-09-11T20:06:48Z INFO librespot_core::session] Authenticated as "xxx" !
[2024-09-11T20:06:48Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-09-11T20:06:48Z INFO librespot_playback::convert] Converting with ditherer: tpdf
[2024-09-11T20:06:48Z INFO librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2024-09-11T20:06:48Z INFO librespot_core::session] Country: "DE"
[2024-09-11T20:06:48Z INFO librespot_playback::audio_backend::rodio] Using audio device: default
[2024-09-11T20:06:49Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:4vWfES1aalWtGA6cFTiFSw
[2024-09-11T20:06:49Z ERROR librespot_playback::player] hmk: format: OGG_VORBIS_96
[2024-09-11T20:06:49Z ERROR librespot_playback::player] hmk: spotify_id: spotify:track:4vWfES1aalWtGA6cFTiFSw
[2024-09-11T20:06:49Z ERROR librespot_playback::player] hmk: file_id: f5caad7850c877bf78535c87b5aa1c4e9710817c
[2024-09-11T20:06:51Z INFO librespot_playback::player] (347826 ms) loaded
^C[2024-09-11T20:07:02Z INFO librespot] Gracefully shutting down

Can someone confirm that "--bitrate 96" also has an issue playing songs?

@kingosticks
Copy link
Contributor

Could it be related to gew4 being used in 0.5? The 0.4 log contains

librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80

@roderickvd do you remember why gew4 is allowed again in 0.5? The specific code to avoid using it isn't there? Is it intentional or accidental?

@roderickvd
Copy link
Member

I remember it was intentional. Don't remember but I think the errors on 0.4 did not seem to apply to 0.5 on that AP. Sorry, can't remember any more details.

Does this 96 kbps work again when you ignore that AP? For sure I've never tested that bitrate myself.

Or maybe there's something in the code that selects the most appropriate bitrate, that tries to get a key for a different file with different bitrate? Just a wild guess. I do think I touched that piece of code when I added some boilerplate for future FLAC support.

@kingosticks
Copy link
Contributor

kingosticks commented Sep 16, 2024

Can someone confirm that "--bitrate 96" also has an issue playing songs?

Yep (v0.5.0-dev)

[2024-09-16T16:01:27Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2024-09-16T16:01:27Z INFO  librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
[2024-09-16T16:01:27Z INFO  librespot_playback::player] Loading <Thank You Buddy> with Spotify URI <spotify:track:3SCWI102atEPe8i7v2jURK>
[2024-09-16T16:01:27Z INFO  librespot_connect::spirc] Resolved 50 tracks from <"spotify:album:29vZTo6729BRVrZVOBHBdH">
[2024-09-16T16:01:28Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-16T16:01:28Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2024-09-16T16:01:32Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2024-09-16T16:01:32Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3SCWI102atEPe8i7v2jURK")>: ()
[2024-09-16T16:01:32Z INFO  librespot_playback::player] Loading <The Milk> with Spotify URI <spotify:track:57GXoM0Bf9FhO39q7R0OBJ>
[2024-09-16T16:01:32Z INFO  librespot_playback::player] Loading <A Good Thing> with Spotify URI <spotify:track:6rYTM9kpZKVjI2AiwJ2kxg>
[2024-09-16T16:01:32Z INFO  librespot_connect::spirc] Resolved 50 tracks from <"spotify:artist:6GKzHklwb2dpXc1Pqg067x">
[2024-09-16T16:01:33Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-16T16:01:33Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2024-09-16T16:01:33Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-16T16:01:33Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
^C[2024-09-16T16:01:37Z INFO  librespot] Gracefully shutting down
[2024-09-16T16:01:45Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: Deadline expired before operation could complete { wait timeout exceeded }
[2024-09-16T16:01:45Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: Deadline expired before operation could complete { wait timeout exceeded }

The other two bitrates work fine for me.

@roderickvd
Copy link
Member

This seems like an important regression which must be fixed before 0.5 goes out. Who is willing to work on it?

@fivebanger
Copy link
Contributor Author

fivebanger commented Sep 16, 2024

Does this 96 kbps work again when you ignore that AP? For sure I've never tested that bitrate myself.

@roderickvd This issue happens also when blocking "https://apresolve.spotify.com/" and librespot uses its fallback AP. No idea about other AP's, I have not tried to revert blocking of specific AP's in v0.5.0-dev like done in v0.4.2.

v0.5.0 log (with fallback AP):

[2024-09-16T18:20:25Z INFO  librespot] librespot 0.5.0-dev VERGEN_IDEMPOTENT_OUTPUT (Built on 2024-09-03, Build ID: upyelh1p, Profile: release)
[2024-09-16T18:20:25Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-09-16T18:20:25Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2024-09-16T18:20:25Z INFO  librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2024-09-16T18:20:25Z INFO  librespot_playback::audio_backend::rodio] Using audio device: default
[2024-09-16T18:20:38Z WARN  librespot_core::apresolve] Failed to resolve all access points, using fallbacks
[2024-09-16T18:20:38Z WARN  librespot_core::apresolve] Resolve access points error: Service unavailable { client error (Connect) }
[2024-09-16T18:20:38Z INFO  librespot_core::session] Connecting to AP "ap.spotify.com:443"
[2024-09-16T18:20:38Z INFO  librespot_core::session] Authenticated as "xxx" !
[2024-09-16T18:20:38Z INFO  librespot_core::session] Country: "DE"
[2024-09-16T18:20:38Z WARN  librespot_core::apresolve] Failed to resolve all access points, using fallbacks
[2024-09-16T18:20:38Z WARN  librespot_core::apresolve] Resolve access points error: Service unavailable { client error (Connect) }
[2024-09-16T18:20:38Z INFO  librespot_core::spclient] Resolved "spclient.wg.spotify.com:443" as spclient access point
[2024-09-16T18:20:38Z WARN  librespot_core::apresolve] Failed to resolve all access points, using fallbacks
[2024-09-16T18:20:38Z WARN  librespot_core::apresolve] Resolve access points error: Service unavailable { client error (Connect) }
[2024-09-16T18:20:38Z INFO  librespot_core::spclient] Resolved "spclient.wg.spotify.com:443" as spclient access point
[2024-09-16T18:20:39Z ERROR librespot_connect::spirc] ContextError: Error { kind: Unknown, error: StatusCode(502) }
[2024-09-16T18:20:39Z INFO  librespot_playback::player] Loading <Spaceman> with Spotify URI <spotify:track:0uQcP7QVoLvaFsORsdrgNh>
[2024-09-16T18:20:39Z ERROR librespot_playback::player] hmk, line 996: format: OGG_VORBIS_96
[2024-09-16T18:20:39Z ERROR librespot_playback::player] hmk, line 997: spotify_id: spotify:track:0uQcP7QVoLvaFsORsdrgNh
[2024-09-16T18:20:39Z ERROR librespot_playback::player] hmk, line 998: file_id: c91072a07a3a45f7666ac2302766dc8165434602
[2024-09-16T18:20:39Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-16T18:20:39Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2024-09-16T18:20:41Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2024-09-16T18:20:41Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0uQcP7QVoLvaFsORsdrgNh")>: ()
[2024-09-16T18:20:41Z INFO  librespot_playback::player] Loading <You Oughta Know - 2015 Remaster> with Spotify URI <spotify:track:3jS7bB0oXVOwGFZn3aE5NV>
[2024-09-16T18:20:41Z ERROR librespot_playback::player] hmk, line 996: format: OGG_VORBIS_96
[2024-09-16T18:20:41Z ERROR librespot_playback::player] hmk, line 997: spotify_id: spotify:track:3jS7bB0oXVOwGFZn3aE5NV
[2024-09-16T18:20:41Z ERROR librespot_playback::player] hmk, line 998: file_id: 9062385e1738325c74fa165c64ba2154873cfece
[2024-09-16T18:20:41Z ERROR librespot_core::audio_key] error audio key 0 1
[2024-09-16T18:20:41Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
^C[2024-09-16T18:20:43Z INFO  librespot] Gracefully shutting down
[2024-09-16T18:20:51Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: Deadline expired before operation could complete { wait timeout exceeded }

@fivebanger
Copy link
Contributor Author

fivebanger commented Sep 16, 2024

I have added additional debug prints in v0.4.2 as well as in v0.5.0 inside player.rs, fn load_track() in order to get the AudioItem struct or audio struct respectively.

This is the trace for "AudioItem" struct, 96kbps, v0.5.0:

{ track_id: SpotifyId("spotify:track:3jS7bB0oXVOwGFZn3aE5NV"), uri: "spotify:track:3jS7bB0oXVOwGFZn3aE5NV", files: AudioFiles({

OGG_VORBIS_96: FileId(Ok("9062385e1738325c74fa165c64ba2154873cfece")), 
AAC_24: FileId(Ok("84ceeeeb49363c91bf1e5c509a089e6a4b85b550")), 
OGG_VORBIS_320: FileId(Ok("8e75b073e2e6efaa639d1b84c243fe747d7c518c")), 
OGG_VORBIS_160: FileId(Ok("a7734f26618ebdb6996aee5e14479e1442ef9a7d"))}), 

name: "You Oughta Know - 2015 Remaster", covers: [CoverImage { url: "https://i.scdn.co/image/ab67616d0000b273242e643ea07118ecf677a6ef", size: LARGE, width: 640, height: 640 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00001e02242e643ea07118ecf677a6ef", size: DEFAULT, width: 300, height: 300 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00004851242e643ea07118ecf677a6ef", size: SMALL, width: 64, height: 64 }], language: ["en"], duration_ms: 249493, is_explicit: true, availability: Ok(()), alternatives: None, unique_fields: Track { artists: ArtistsWithRole([ArtistWithRole { id: SpotifyId("spotify:artist:6ogn9necmbUdCppmNnGOdi"), name: "Alanis Morissette", role: ARTIST_ROLE_MAIN_ARTIST }]), album: "Jagged Little Pill - 2015 Remaster", album_artists: ["Alanis Morissette"], popularity: 67, number: 2, disc_number: 1 } }

hmk, line 996: format: OGG_VORBIS_96
hmk, line 997: spotify_id: spotify:track:3jS7bB0oXVOwGFZn3aE5NV
hmk, line 998: file_id: 9062385e1738325c74fa165c64ba2154873cfece

This is the trace for "audio" struct, 96kbps, v0.4.2:

{ id: SpotifyId { id: 145021649363201307109311018513601295979, audio_type: Track }, uri: "spotify:track:3jS7bB0oXVOwGFZn3aE5NV", files: {

AAC_320: FileId(Ok("926b60d8d6d7fc5fa94b3f85cf61ce1f7d9c18e8")), 
MP4_128_DUAL: FileId(Ok("84ceeeeb49363c91bf1e5c509a089e6a4b85b550")), 
OTHER5: FileId(Ok("0e01e269fd3e63138da748d6be74dc99f6c5f1b7")), 
OGG_VORBIS_96: FileId(Ok("32f4a529f40bafb9abd834b853f9a25425b78dd4")), 
OGG_VORBIS_320: FileId(Ok("8e75b073e2e6efaa639d1b84c243fe747d7c518c")), 
OGG_VORBIS_160: FileId(Ok("a7734f26618ebdb6996aee5e14479e1442ef9a7d")), 
MP4_128: FileId(Ok("6df9ea6ec96ce6985e05c18279722e7baa7ff767")), 
AAC_160: FileId(Ok("9062385e1738325c74fa165c64ba2154873cfece"))}, 

name: "You Oughta Know - 2015 Remaster", duration: 249493, available: true, alternatives: Some([]) }


[2024-09-16T19:32:13Z ERROR librespot_playback::player] hmk: format: OGG_VORBIS_96
[2024-09-16T19:32:13Z ERROR librespot_playback::player] hmk: spotify_id: spotify:track:3jS7bB0oXVOwGFZn3aE5NV
[2024-09-16T19:32:13Z ERROR librespot_playback::player] hmk: file_id: 32f4a529f40bafb9abd834b853f9a25425b78dd4

For v0.5.0 the used file_id results in "9062385e1738325c74fa165c64ba2154873cfece" which is mapped to "OGG_VORBIS_96" in "AudioItem".
For v0.4.2 the used file_id results in "32f4a529f40bafb9abd834b853f9a25425b78dd4" which is also mapped to "OGG_VORBIS_96" in "audio".

This fits to my observation that v0.4.2 uses a different file_id compared to v0.5.0 for the same spotify_id. The interesting thing is that the file_id "9062385e1738325c74fa165c64ba2154873cfece" which is used in v0.5.0 is the file_id which is mapped to "AAC_160" for v0.4.2. Beside that there are some more audio formats available when using v0.4.2.

I tried to follow up where the "files"-field is populated in v0.5.0 and ended up somewhere in parse_from_bytes() inside messages.rs. No idea about the code there currently....

Edit:
The file_ids for "OGG_VORBIS_320" and "OGG_VORBIS_160" are the same for v0.4.2 and v0.5.0. I guess that's why 320kbps and 160kbps works in 0.4.2 as well as in 0.5.0.

@kingosticks
Copy link
Contributor

Very interesting!

I might be misunderstanding this but the protobuf code here looks a bit suspicious to me. Is it using OGG_VORBIS_96 as the default when it doesn't understand it?

 pub fn format(&self) -> audio_file::Format {
        match self.format {
            Some(e) => e.enum_value_or(audio_file::Format::OGG_VORBIS_96),
            None => audio_file::Format::OGG_VORBIS_96,
        }
    }

So if a value isn't defined in the .proto enum (shown below) then it'll be given OGG_VORBIS_96? And we create a HashMap<AudioFileFormat, FileId> so if there are unknown entries after a real OGG_VORBIS_96 entry, our returned hashmap will contain the last unknown one?

0.4:

message AudioFile {
    optional bytes file_id = 0x1;
    optional Format format = 0x2;
    enum Format {
        OGG_VORBIS_96 = 0x0;
        OGG_VORBIS_160 = 0x1;
        OGG_VORBIS_320 = 0x2;
        MP3_256 = 0x3;
        MP3_320 = 0x4;
        MP3_160 = 0x5;
        MP3_96 = 0x6;
        MP3_160_ENC = 0x7;
        // v4 
        // AAC_24 = 0x8;
        // AAC_48 = 0x9;
        MP4_128_DUAL = 0x8;
        OTHER3 = 0x9;
        AAC_160 = 0xa;
        AAC_320 = 0xb;
        MP4_128 = 0xc;
        OTHER5 = 0xd;
    }
}

0.5:

message AudioFile {
    optional bytes file_id = 1;
    
    optional Format format = 2;
    enum Format {
        OGG_VORBIS_96 = 0;
        OGG_VORBIS_160 = 1;
        OGG_VORBIS_320 = 2;
        MP3_256 = 3;
        MP3_320 = 4;
        MP3_160 = 5;
        MP3_96 = 6;
        MP3_160_ENC = 7;
        AAC_24 = 8;
        AAC_48 = 9;
        FLAC_FLAC = 16;
    }
}

@kingosticks
Copy link
Contributor

Yes, I think that's what is happening. Adding

        AAC_160 = 0xa;
        AAC_320 = 0xb;
        MP4_128 = 0xc;
        OTHER5 = 0xd;

to the v0.5 proto definition fixes 96kbps playback for me.

@roderickvd
Copy link
Member

roderickvd commented Sep 17, 2024

Great! Probably should let go of OTHER5 = 0xa which now maps to FLAC_FLAC = 16.

@fivebanger
Copy link
Contributor Author

Yes, I think that's what is happening. Adding

        AAC_160 = 0xa;
        AAC_320 = 0xb;
        MP4_128 = 0xc;
        OTHER5 = 0xd;

to the v0.5 proto definition fixes 96kbps playback for me.

@kingosticks Thanks a lot. This seems to fix the issue with 96kbps as well as the issue with the podcast episodes. Need to do some more testing....

But just to double check: I found message AudioFile {...} in two places: media_manifest.proto and metadata.proto. I have added your extension to both, don't know if this is correct?

I have to add some code inside player.rs as well to make it compile. I guess that's correct, too?

    fn stream_data_rate(&self, format: AudioFileFormat) -> usize {
        let kbps = match format {
            AudioFileFormat::OGG_VORBIS_96 => 12,
            AudioFileFormat::OGG_VORBIS_160 => 20,
            AudioFileFormat::OGG_VORBIS_320 => 40,
            AudioFileFormat::MP3_256 => 32,
            AudioFileFormat::MP3_320 => 40,
            AudioFileFormat::MP3_160 => 20,
            AudioFileFormat::MP3_96 => 12,
            AudioFileFormat::MP3_160_ENC => 20,
            AudioFileFormat::AAC_24 => 3,
            AudioFileFormat::AAC_48 => 6,
            
            /* additional lines */
            AudioFileFormat::AAC_160 => 20,
            AudioFileFormat::AAC_320 => 40,
            AudioFileFormat::MP4_128 => 16,
            AudioFileFormat::OTHER5 => 40,
            
            AudioFileFormat::FLAC_FLAC => 112, // assume 900 kbit/s on average

            /* from v0.4.2
            FileFormat::OGG_VORBIS_96 => 12 * 1024,
            FileFormat::OGG_VORBIS_160 => 20 * 1024,
            FileFormat::OGG_VORBIS_320 => 40 * 1024,
            FileFormat::MP3_256 => 32 * 1024,
            FileFormat::MP3_320 => 40 * 1024,
            FileFormat::MP3_160 => 20 * 1024,
            FileFormat::MP3_96 => 12 * 1024,
            FileFormat::MP3_160_ENC => 20 * 1024,
            FileFormat::MP4_128_DUAL => 16 * 1024,
            FileFormat::OTHER3 => 40 * 1024, // better some high guess than nothing
            FileFormat::AAC_160 => 20 * 1024,
            FileFormat::AAC_320 => 40 * 1024,
            FileFormat::MP4_128 => 16 * 1024,
            FileFormat::OTHER5 => 40 * 1024, // better some high guess than nothing
            */
        };
        kbps * 1024
    }

When comparing v0.4 with v0.5, OTHER3 = 9 is now mapped to AAC_48 = 9. I guess that's by intention?

@michaelherger
Copy link
Contributor

guys, you rock! What would be the minimum change I'd have to apply to test the podcast issue?

@fivebanger
Copy link
Contributor Author

guys, you rock! What would be the minimum change I'd have to apply to test the podcast issue?

@michaelherger Adding

        AAC_160 = 0xa;
        AAC_320 = 0xb;
        MP4_128 = 0xc;
        OTHER5 = 0xd;

to message AudioFile {...} in media_manifest.proto and metadata.proto

and adding

            AudioFileFormat::AAC_160 => 20,
            AudioFileFormat::AAC_320 => 40,
            AudioFileFormat::MP4_128 => 16,
            AudioFileFormat::OTHER5 => 40,

inside

fn stream_data_rate(&self, format: AudioFileFormat) -> usize {
        let kbps = match format {

in player.rs is doing the trick for me.

@kingosticks
Copy link
Contributor

Yes, sorry, I just added something silly to fix the compile error, it wasn't going to actually be using those extra formats.

Re the other proto file. I didn't check if we were using that other one but I think in general it makes sense that all code points are covered if the generated proto hides issues like this. I wonder if we can make it emit a warning message or something when it does that.

@michaelherger
Copy link
Contributor

Excellent! I can confirm that the podcasts which previously wouldn't work any more now are working for me, too (after manually applying the above changes to my own fork).

michaelherger added a commit to michaelherger/librespot that referenced this issue Sep 17, 2024
@fivebanger
Copy link
Contributor Author

fivebanger commented Sep 17, 2024

But I don't understand the issue yet in details. My understanding is:

We're requesting information from Spotify (e.g. the file_ids).
Spotify is returning kind of byte-stream (or so) which we need to parse.
There is a byte (or word; let's say "id") inside the returned msg that indicates the file_id for a certain audio format.
The id-mapping is done in message AudioFile {...} which represents an enum.
Some values were not defined in v0.5.
But the mapping for OGG_VORBIS_96 = 0 was defined.
And that's what we have requested.
And I guess Spotify has delivered the proper file_id for OGG_VORBIS_96 inside its return message (byte-stream?).
So we were not able to properly parse the missing ids and map them to a proper file_id, but, so what? We're not interested in those anyway...

So I'm wondering: The missing definitions for

        AAC_160 = 0xa;
        AAC_320 = 0xb;
        MP4_128 = 0xc;
        OTHER5 = 0xd;

led to the observed issue with 96kbps and some podcast episodes.

What, if Spotify returns a new audio format, something like FANCY_NEW_FORMAT = 0xe in future? We don't have covered that one, too as of today. Will this lead to an issue as well?

Edit:
And, more over, why the file_id which is targeting to AAC_160 ends up in OGG_VORBIS_96 at the end in v0.5?

@acid-sun
Copy link

acid-sun commented Sep 17, 2024

I have same problem with error audio key 0 2. Client show progress playing, but no sound from librespot (latest build from git dev).

[2024-09-17T08:50:31Z TRACE librespot_audio::fetch] Streaming from https://audio-ak-spotify-com.akamaized.net/audio/1ec2eb082880af0deb56ec525f0beee995c53c82?__token__=exp=1726649431~hmac=xxx
[2024-09-17T08:50:31Z ERROR librespot_core::audio_key] error audio key 0 2
[2024-09-17T08:50:31Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 40 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1170 kbps
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 35 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 930 kbps
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 40 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 786 kbps
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 31 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1255 kbps
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 21 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1684 kbps
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 34 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2256 kbps
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 18 ms
[2024-09-17T08:50:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2493 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2661 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 16 ms
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2272 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3063 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 13 ms
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2914 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2421 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3215 kbps
[2024-09-17T08:50:32Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3386 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2829 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2471 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2813 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 14 ms
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2225 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 19 ms
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2478 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2877 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2107 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 15 ms
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2692 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3142 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2878 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2531 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2697 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3239 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2790 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2291 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2784 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3212 kbps
[2024-09-17T08:50:33Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3205 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2528 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 18 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 22 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 18 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 20 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 17 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 20 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3044 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 15 ms
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2498 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3087 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2828 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2350 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2037 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2342 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3045 kbps
[2024-09-17T08:50:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3450 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1911 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 30 ms
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2449 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 18 ms
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2785 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 16 ms
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3172 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 14 ms
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2613 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 33 ms
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1975 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2412 kbps
[2024-09-17T08:50:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 25 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2025 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 19 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2378 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3009 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 14 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3325 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2090 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2683 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3162 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2681 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 27 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2160 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2640 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 17 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2260 kbps
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 21 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 15 ms
[2024-09-17T08:50:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2359 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1513 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2577 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3013 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2676 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2274 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1234 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 17 ms
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2177 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2813 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2439 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2858 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 14 ms
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3153 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3086 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 21 ms
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2173 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 46 ms
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1598 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2288 kbps
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 19 ms
[2024-09-17T08:50:37Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2569 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3017 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 15 ms
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2776 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 19 ms
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 15 ms
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3320 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2666 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 26 ms
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1697 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2669 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 14 ms
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2972 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3414 kbps
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 16 ms
[2024-09-17T08:50:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2360 kbps
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 1363 kbps
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2406 kbps
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 13 ms
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3130 kbps
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 19 ms
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 13 ms
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 3266 kbps
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 20 ms
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 2846 kbps
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 13 ms
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 20 ms
[2024-09-17T08:50:39Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 14 ms
[2024-09-17T08:50:39Z DEBUG librespot_audio::fetch] Downloading file 1ec2eb082880af0deb56ec525f0beee995c53c82 complete
[2024-09-17T08:50:39Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2024-09-17T08:50:39Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0CECbcanOoDprkHvuutPN4")>: ()
[2024-09-17T08:50:39Z DEBUG librespot_connect::spirc] Marked <TrackRef { gid: Some([20, 124, 56, 164, 187, 208, 75, 13, 167, 118, 53, 51, 41, 30, 162, 38]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at 12 as NonPlayable

@kingosticks
Copy link
Contributor

kingosticks commented Sep 17, 2024

And I guess Spotify has delivered the proper file_id for OGG_VORBIS_96 inside its return message (byte-stream?).

Yes.

So we were not able to properly parse the missing ids and map them to a proper file_id, but, so what? We're not interested in those anyway...

The issue is the generated protobuf code that parses the bytestream and converts it into the Metadata::AudioFile::Format::Format type, that code is in the first snippet at #1236 (comment). When it discovers a value it doesn't recognise, instead of ignoring it or producing an error, it converts it into the default value (the first one defined in the .proto), which is OGG_VORBIS_96. So when every "unknown" format becomes OGG_VORBIS_96, we get extra files erroneously designated to be in OGG_VORBIS_96 format. Our code then loops through the list of files and puts them into a HashMap keyed by Format. If there are any files with the same Format, the last one will have overwritten all the others. The result is what we think is OGG_VORBIS_96, is actually one of the unknown formats.

fn from(files: &[AudioFileMessage]) -> Self {
let audio_files: HashMap<AudioFileFormat, FileId> = files
.iter()
.filter_map(|file| {
let file_id = FileId::from(file.file_id());
if file.has_format() {
Some((file.format(), file_id))
} else {
trace!("Ignoring file <{}> with unspecified format", file_id);
None
}
})
.collect();
AudioFiles(audio_files)

What, if Spotify returns a new audio format, something like FANCY_NEW_FORMAT = 0xe in future? We don't have covered that one, too as of today. Will this lead to an issue as well?

Yes. And it would be great to avoid that, maybe we can here. But there are probably lots of other places like this.

@fivebanger
Copy link
Contributor Author

@kingosticks Ah, ok, I understand. Thanks a lot for your detailed explanation. Now it's clear to me what happens. Avoiding those kind of issues would be great, even though my Rust skills are to limited yet to understand the code by my self and have even a rough idea how to fix...

@kingosticks
Copy link
Contributor

kingosticks commented Sep 17, 2024

It seems the protobuf spec allows a default to be set. e.g.

message AudioFile {
    optional bytes file_id = 1;
    
    optional Format format = 2 [default = UNKNOWN];
    enum Format {
        OGG_VORBIS_96 = 0;
        OGG_VORBIS_160 = 1;
        OGG_VORBIS_320 = 2;
        MP3_256 = 3;
        MP3_320 = 4;
        MP3_160 = 5;
        MP3_96 = 6;
        MP3_160_ENC = 7;
        AAC_24 = 8;
        AAC_48 = 9;
        FLAC_FLAC = 16;
        UNKNOWN = 17;
    }
}

But I couldn't get the protobuf parser to accept that.

EDIT: Turns out the default syntax is for proto3 format only, ours our proto2.

EDIT EDIT: Or I guess we could change our from<AudioFileMessage> function to use file.format rather than file.format() and handle EnumOrUnknown directly ourselves and do the right thing?

@roderickvd
Copy link
Member

The protobufs extracted are in fact proto2 so let's stick to that. Then handling it ourselves would be nice indeed, but let's be honest, also likely an edge case.

Who will put in a PR to fix the 96 kbps thing? With or without the default fallback.

@michaelherger
Copy link
Contributor

I wish I could 😞.

@fivebanger
Copy link
Contributor Author

I'm confused now... What I understood so far: The "metadata.rs" file is generated by some generator and located somewhere under ../target/debug/build/.. and ../target/release/build/.. . The input for the generator is "metadat.proto". I assume my understanding is correct so far.
Since I have no idea how to change code inside "file.rs" (the thing with file.format vs. file.format()) I started to play around with "metadat.proto" file. I'm pretty sure I have read also something with respect to [default = DEFAULT_VAL] and proto2 vs. proto3, but don't find it anymore. Anyway, long sorry short, what I did:

Deleted all the generated files related "librespot-protocol" under ../target/debug/build/.. and ../target/release/build/.. just to be sure.

Changed message AudioFile {...} to

message AudioFile {
    optional bytes file_id = 1;
    
    optional Format format = 2 [default = UNKNOWN_FORMAT];
    enum Format {
        OGG_VORBIS_96 = 0;
        OGG_VORBIS_160 = 1;
        OGG_VORBIS_320 = 2;
        MP3_256 = 93;
        MP3_320 = 94;
        MP3_160 = 95;
        MP3_96 = 96;
        MP3_160_ENC = 97;
        AAC_24 = 98;
        AAC_48 = 99;
        AAC_160 = 110;
        AAC_320 = 111;
        MP4_128 = 112;
        OTHER5 = 113;
        FLAC_FLAC = 116;
        UNKNOWN_FORMAT = 255;
    }
}

using some nonsense values for all non OGG formats, just to provoke a lot of unknown errors (and not touching the rest of the code). I have used "UNKNOWN_FORMAT" for better searching over files, works also with "UNKNOWN".

This change results in

    pub fn format(&self) -> audio_file::Format {
        match self.format {
            Some(e) => e.enum_value_or(audio_file::Format::UNKNOWN_FORMAT),
            None => audio_file::Format::UNKNOWN_FORMAT,
        }
    }

inside the generated "metadata.rs" file.

I added a handler for "UNKNOWN_FORMAT" also in player.rs

            AudioFileFormat::UNKNOWN_FORMAT => 40,

which seems to be kind of stupid, calculating a data rate for an unknown format.

As a result I get this AudioItem struct:

AudioItem { track_id: SpotifyId("spotify:track:3jS7bB0oXVOwGFZn3aE5NV"), uri: "spotify:track:3jS7bB0oXVOwGFZn3aE5NV", files: AudioFiles({

OGG_VORBIS_160: FileId(Ok("a7734f26618ebdb6996aee5e14479e1442ef9a7d")), 
OGG_VORBIS_96: FileId(Ok("32f4a529f40bafb9abd834b853f9a25425b78dd4")), 
OGG_VORBIS_320: FileId(Ok("8e75b073e2e6efaa639d1b84c243fe747d7c518c")), 
UNKNOWN_FORMAT: FileId(Ok("84ceeeeb49363c91bf1e5c509a089e6a4b85b550"))}), 

name: "You Oughta Know - 2015 Remaster", covers: [CoverImage { url: "https://i.scdn.co/image/ab67616d0000b273242e643ea07118ecf677a6ef", size: LARGE, width: 640, height: 640 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00001e02242e643ea07118ecf677a6ef", size: DEFAULT, width: 300, height: 300 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00004851242e643ea07118ecf677a6ef", size: SMALL, width: 64, height: 64 }], language: ["en"], duration_ms: 249493, is_explicit: true, availability: Ok(()), alternatives: None, unique_fields: Track { artists: ArtistsWithRole([ArtistWithRole { id: SpotifyId("spotify:artist:6ogn9necmbUdCppmNnGOdi"), name: "Alanis Morissette", role: ARTIST_ROLE_MAIN_ARTIST }]), album: "Jagged Little Pill - 2015 Remaster", album_artists: ["Alanis Morissette"], popularity: 67, number: 2, disc_number: 1 } }

and this is the result after all

hmk, line 996: format: OGG_VORBIS_96\n'
hmk, line 997: spotify_id: spotify:track:3jS7bB0oXVOwGFZn3aE5NV
hmk, line 998: file_id: 32f4a529f40bafb9abd834b853f9a25425b78dd4

The file_ids seems to be correct (compared to my comment #1236 (comment)) and 96kbps and episodes works well.

@kingosticks So basically I just did the same as you have proposed. Can you pls. double check once again on your side that this code works? Do I miss something on my side, is there an error?

kingosticks added a commit to kingosticks/librespot that referenced this issue Sep 17, 2024
Prevents unknown formats being treated as `OGG_VORBIS_96` and breaking
96kbps playback. Fixes librespot-org#1236.
@kingosticks
Copy link
Contributor

That looks OK to me.

In my earlier post I claimed that the [default = X] syntax for enums was only available for proto3 files and when I tried it earlier on my work computer I'm sure it failed to compile, but it's working just fine now at home. My turn to be confused. I can now see it's also already used in other proto2 files we have, and the proto2 spec actually says it's OK, and supported in rust-protobuf since 2018!, and it compiles fine now! So yes, let's use that feature to help fix this.

Maybe just say the stream_data_rate for UNKNOWN_FORMAT is 0? Or something like this is more sensible?

@fivebanger
Copy link
Contributor Author

fivebanger commented Sep 18, 2024

I like the approach to return None for stream_data_rate. It's a clear statement that here is something wrong. But if we manage to return None for stream_data_rate for whatever reason it seems we get stuck inside AudioFile::open(&self.session, file_id, bytes_per_second);. I checked by forcing

            AudioFileFormat::UNKNOWN_FORMAT => {
                error!("Unknown stream data rate");
                return None
            }
            AudioFileFormat::OGG_VORBIS_96 => {
                error!("Unknown stream data rate");
                return None
            }

That's maybe kind of theoretical discussion and the approach to force None by using AudioFileFormat::OGG_VORBIS_96 => { is a mismatch between expected formats and non-expected formats which is covered at other places most likely. I just want to point out.

In sum I see the following code changes up to now:

media_manifest.proto (no idea about a default here, but its proto3 syntax anyway, maybe does not work?) :

message AudioFile {
    enum Format {
        OGG_VORBIS_96 = 0;
        OGG_VORBIS_160 = 1;
        OGG_VORBIS_320 = 2;
        MP3_256 = 3;
        MP3_320 = 4;
        MP3_160 = 5;
        MP3_96 = 6;
        MP3_160_ENC = 7;
        AAC_24 = 8;
        AAC_48 = 9;
        AAC_160 = 10;
        AAC_320 = 11;
        MP4_128 = 12;
        OTHER5 = 13;
        FLAC_FLAC = 16;
    }
}

metadata.proto (not sure about the numerical value for UNKNOWN_FORMAT, thought 0xFF would be a good idea):

message AudioFile {
    optional bytes file_id = 1;
    
    optional Format format = 2 [default = UNKNOWN_FORMAT];
    enum Format {
        OGG_VORBIS_96 = 0;
        OGG_VORBIS_160 = 1;
        OGG_VORBIS_320 = 2;
        MP3_256 = 3;
        MP3_320 = 4;
        MP3_160 = 5;
        MP3_96 = 6;
        MP3_160_ENC = 7;
        AAC_24 = 8;
        AAC_48 = 9;
        AAC_160 = 10;
        AAC_320 = 11;
        MP4_128 = 12;
        OTHER5 = 13;
        FLAC_FLAC = 16;
        UNKNOWN_FORMAT = 255;
    }
}

player.rs:

    fn stream_data_rate(&self, format: AudioFileFormat) -> Option<usize> {
        let kbps = match format {
            AudioFileFormat::OGG_VORBIS_96 => 12,
            AudioFileFormat::OGG_VORBIS_160 => 20,
            AudioFileFormat::OGG_VORBIS_320 => 40,
            AudioFileFormat::MP3_256 => 32,
            AudioFileFormat::MP3_320 => 40,
            AudioFileFormat::MP3_160 => 20,
            AudioFileFormat::MP3_96 => 12,
            AudioFileFormat::MP3_160_ENC => 20,
            AudioFileFormat::AAC_24 => 3,
            AudioFileFormat::AAC_48 => 6,
            AudioFileFormat::AAC_160 => 20,
            AudioFileFormat::AAC_320 => 40,
            AudioFileFormat::MP4_128 => 16,
            AudioFileFormat::OTHER5 => 40,
            AudioFileFormat::FLAC_FLAC => 112, // assume 900 kbit/s on average
            AudioFileFormat::UNKNOWN_FORMAT => {
                error!("Unknown stream data rate");
                return None
            }
        };
        Some(kbps * 1024)
    }

and

        let bytes_per_second = self.stream_data_rate(format)?;

Edit:
Forget about that stuck issue regarding AudioFile::open(&self.session, file_id, bytes_per_second); for bytes_per_second is None, maybe I'm wrong here. Just wondering what happens if bytes_per_second is None, not sure yet, need more investigation. I get some trace output I cannot explain yet. Anyway, I'm wondering if "bytes_per_second is None" should be handled somehow before AudioFile::open(&self.session, file_id, bytes_per_second);.

Edit:
So the "?" at the end of let bytes_per_second = self.stream_data_rate(format)?; is already handling the "None" case? So no issue here?

@kingosticks
Copy link
Contributor

So the "?" at the end of let bytes_per_second = self.stream_data_rate(format)?; is already handling the "None" case? So no issue here?

Yep. Why don't you create a PR with these changes, that's a better place for a review.

@fivebanger
Copy link
Contributor Author

I'm not used to work on community projects like this yet. I need to check this pull-request stuff first, I'm not really familiar with Git. Just give me some time.

Sorry for some stupid output or questions from my side sometimes, but it seems I have to cache up and ramp up my learning curve with respect to a lot of topics... :-)

@michaelherger
Copy link
Contributor

See eg. here for an introduction to pull requests: https://docs.github.com/en/pull-requests/collaborating-with-pull-requests/proposing-changes-to-your-work-with-pull-requests/creating-a-pull-request. I can't help with the coding, but feel free to reach out to me if you need help with the Github interaction. That way I could at least contribute to the solution of this problem 😁.

@fivebanger
Copy link
Contributor Author

I have started a pull request for this issue. Since that's my first community pull request, pls. give some advice whenever I should do things different (e.g. with respect to "best practice") or if there's something wrong.

roderickvd pushed a commit that referenced this issue Sep 19, 2024
- add missing audio formats to message AudioFile
- ensure that unknown formats gets mapped to DEFAULT_FORMAT
@kingosticks
Copy link
Contributor

This was fixed in #1342.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

6 participants