mirror of
https://github.com/librespot-org/librespot.git
synced 2026-04-27 08:15:50 +03:00
[GH-ISSUE #1236] error audio key, unable to load key #565
Labels
No labels
A-Alsa
SpotifyAPI
Tokio 1.0
audio
bug
can't reproduce
compilation
dependencies
duplicate
enhancement
good first issue
help wanted
high priority
imported
imported
invalid
new api
pull-request
question
reverse engineering
wiki
wontfix
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
starred/librespot#565
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Originally created by @fivebanger on GitHub (Dec 27, 2023).
Original GitHub issue: https://github.com/librespot-org/librespot/issues/1236
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:
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
librespoton):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.).
@michaelherger commented on GitHub (Sep 14, 2024):
@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 commented on GitHub (Sep 15, 2024):
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 commented on GitHub (Sep 15, 2024):
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:
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 commented on GitHub (Sep 15, 2024):
Does this only happen with episodes? I have some thoughts, will look later
@michaelherger commented on GitHub (Sep 16, 2024):
FWICT yes. In one case it seemed to not even impact all episodes, but only some, probably the most recent ones.
@fivebanger commented on GitHub (Sep 16, 2024):
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:
$ ./librespot --bitrate 96Log 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 commented on GitHub (Sep 16, 2024):
Could it be related to gew4 being used in 0.5? The 0.4 log contains
@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 commented on GitHub (Sep 16, 2024):
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 commented on GitHub (Sep 16, 2024):
Yep (v0.5.0-dev)
The other two bitrates work fine for me.
@roderickvd commented on GitHub (Sep 16, 2024):
This seems like an important regression which must be fixed before 0.5 goes out. Who is willing to work on it?
@fivebanger commented on GitHub (Sep 16, 2024):
@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):
@fivebanger commented on GitHub (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:
This is the trace for "audio" struct, 96kbps, v0.4.2:
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 commented on GitHub (Sep 16, 2024):
Very interesting!
I might be misunderstanding this but the protobuf code here looks a bit suspicious to me. Is it using
OGG_VORBIS_96as the default when it doesn't understand it?So if a value isn't defined in the .proto enum (shown below) then it'll be given
OGG_VORBIS_96? And we create aHashMap<AudioFileFormat, FileId>so if there are unknown entries after a realOGG_VORBIS_96entry, our returned hashmap will contain the last unknown one?0.4:
0.5:
@kingosticks commented on GitHub (Sep 16, 2024):
Yes, I think that's what is happening. Adding
to the v0.5 proto definition fixes 96kbps playback for me.
@roderickvd commented on GitHub (Sep 17, 2024):
Great! Probably should let go of OTHER5 = 0xa which now maps to FLAC_FLAC = 16.
@fivebanger commented on GitHub (Sep 17, 2024):
@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?
When comparing v0.4 with v0.5, OTHER3 = 9 is now mapped to AAC_48 = 9. I guess that's by intention?
@michaelherger commented on GitHub (Sep 17, 2024):
guys, you rock! What would be the minimum change I'd have to apply to test the podcast issue?
@fivebanger commented on GitHub (Sep 17, 2024):
@michaelherger Adding
to
message AudioFile {...}in media_manifest.proto and metadata.protoand adding
inside
in player.rs is doing the trick for me.
@kingosticks commented on GitHub (Sep 17, 2024):
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 commented on GitHub (Sep 17, 2024):
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).
@fivebanger commented on GitHub (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
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 commented on GitHub (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 commented on GitHub (Sep 17, 2024):
Yes.
The issue is the generated protobuf code that parses the bytestream and converts it into the
Metadata::AudioFile::Format::Formattype, that code is in the first snippet at https://github.com/librespot-org/librespot/issues/1236#issuecomment-2354198760. 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 aHashMapkeyed byFormat. If there are any files with the sameFormat, 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.github.com/librespot-org/librespot@22a8850fe9/metadata/src/audio/file.rs (L47-L61)Yes. And it would be great to avoid that, maybe we can here. But there are probably lots of other places like this.
@fivebanger commented on GitHub (Sep 17, 2024):
@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 commented on GitHub (Sep 17, 2024):
It seems the protobuf spec allows a default to be set. e.g.
But I couldn't get the protobuf parser to accept that.
EDIT: Turns out the
defaultsyntax is for proto3 format only, ours our proto2.EDIT EDIT: Or I guess we could change our
from<AudioFileMessage>function to usefile.formatrather thanfile.format()and handleEnumOrUnknowndirectly ourselves and do the right thing?@roderickvd commented on GitHub (Sep 17, 2024):
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 commented on GitHub (Sep 17, 2024):
I wish I could 😞.
@fivebanger commented on GitHub (Sep 17, 2024):
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.formatvs.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 {...}tousing 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
inside the generated "metadata.rs" file.
I added a handler for "UNKNOWN_FORMAT" also in player.rs
which seems to be kind of stupid, calculating a data rate for an unknown format.
As a result I get this AudioItem struct:
and this is the result after all
The file_ids seems to be correct (compared to my comment https://github.com/librespot-org/librespot/issues/1236#issuecomment-2353864861) 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 commented on GitHub (Sep 17, 2024):
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_rateforUNKNOWN_FORMATis 0? Or something like this is more sensible?@fivebanger commented on GitHub (Sep 18, 2024):
I like the approach to
return Noneforstream_data_rate. It's a clear statement that here is something wrong. But if we manage toreturn Noneforstream_data_ratefor whatever reason it seems we get stuck insideAudioFile::open(&self.session, file_id, bytes_per_second);. I checked by forcingThat'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?) :
metadata.proto (not sure about the numerical value for UNKNOWN_FORMAT, thought 0xFF would be a good idea):
player.rs:
and
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 beforeAudioFile::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 commented on GitHub (Sep 18, 2024):
Yep. Why don't you create a PR with these changes, that's a better place for a review.
@fivebanger commented on GitHub (Sep 18, 2024):
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 commented on GitHub (Sep 18, 2024):
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 commented on GitHub (Sep 19, 2024):
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.
@kingosticks commented on GitHub (Sep 20, 2024):
This was fixed in #1342.