[GH-ISSUE #235] failed retrieving aes key with code 1 #150

Closed
opened 2026-02-28 14:25:47 +03:00 by kerem · 24 comments
Owner

Originally created by @tooxo on GitHub (Oct 21, 2025).
Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/235

On some songs go-librespot seems to be unable to resolve the file id.

level=trace msg="voiding websocket event: will_play"
level=debug msg="selected format OGG_VORBIS_320 (d0573855da5673322a24b048bfae199757fd9e10)" uri="spotify:track:0ffiD4SYlHEifVwzBdPqd7"
level=debug msg="requested aes key for file d0573855da5673322a24b048bfae199757fd9e10, gid: 0ffiD4SYlHEifVwzBdPqd7"
level=error msg="failed advancing to next track" error="failed loading current track (advance to spotify:track:0ffiD4SYlHEifVwzBdPqd7): failed creating stream for spotify:track:0ffiD4SYlHEifVwzBdPqd7: failed retrieving audio key: failed retrieving aes key with code 1"

This is also not solved with a restart. (Using: f4e53554b6)

Originally created by @tooxo on GitHub (Oct 21, 2025). Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/235 On some songs go-librespot seems to be unable to resolve the file id. ```log level=trace msg="voiding websocket event: will_play" level=debug msg="selected format OGG_VORBIS_320 (d0573855da5673322a24b048bfae199757fd9e10)" uri="spotify:track:0ffiD4SYlHEifVwzBdPqd7" level=debug msg="requested aes key for file d0573855da5673322a24b048bfae199757fd9e10, gid: 0ffiD4SYlHEifVwzBdPqd7" level=error msg="failed advancing to next track" error="failed loading current track (advance to spotify:track:0ffiD4SYlHEifVwzBdPqd7): failed creating stream for spotify:track:0ffiD4SYlHEifVwzBdPqd7: failed retrieving audio key: failed retrieving aes key with code 1" ``` This is also not solved with a restart. (Using: f4e53554b6dbe8a38c4a5884be5804a5e4290e9c)
kerem 2026-02-28 14:25:47 +03:00
  • closed this issue
  • added the
    bug
    label
Author
Owner

@devgianlu commented on GitHub (Oct 24, 2025):

I am seeing an increase in failed retrieving aes key with code 1 errors on my side too.

<!-- gh-comment-id:3442851839 --> @devgianlu commented on GitHub (Oct 24, 2025): I am seeing an increase in `failed retrieving aes key with code 1` errors on my side too.
Author
Owner

@devgianlu commented on GitHub (Oct 27, 2025):

Don't quote me on that, but I think they are prepearing to shut down the old key retrieval method.

<!-- gh-comment-id:3452302783 --> @devgianlu commented on GitHub (Oct 27, 2025): Don't quote me on that, but I think they are prepearing to shut down the old key retrieval method.
Author
Owner

@kingosticks commented on GitHub (Oct 27, 2025):

How often are people seeing this? We've seen no reports of this on librespot. It's possible the retry logic is different and hiding it.

<!-- gh-comment-id:3452361690 --> @kingosticks commented on GitHub (Oct 27, 2025): How often are people seeing this? We've seen no reports of this on librespot. It's possible the retry logic is different and hiding it.
Author
Owner

@devgianlu commented on GitHub (Oct 27, 2025):

This is happening to me quite a lot now, like 1 in 4 tracks cannot be played. It's been a while since they last fiddled with this API.

<!-- gh-comment-id:3452391033 --> @devgianlu commented on GitHub (Oct 27, 2025): This is happening to me quite a lot now, like 1 in 4 tracks cannot be played. It's been a while since they last fiddled with this API.
Author
Owner

@kingosticks commented on GitHub (Oct 28, 2025):

I had a closer look and I think if we were seeing AesKeyError in librespot we'd be getting error messages for that and people would be reporting those. So that's odd.

Edit: Maybe worth trying to play the same track with librespot and see if you see the issue then? We have not moved over to storage resolve V2 or the other metadata endpoint. Are the returned fileid/gids different between the old and new endpoints?

<!-- gh-comment-id:3455999840 --> @kingosticks commented on GitHub (Oct 28, 2025): I had a closer look and I think if we were seeing `AesKeyError` in librespot we'd be getting error messages for that and people would be reporting those. So that's odd. Edit: Maybe worth trying to play the same track with librespot and see if you see the issue then? We have not moved over to storage resolve V2 or the other metadata endpoint. Are the returned fileid/gids different between the old and new endpoints?
Author
Owner

@devgianlu commented on GitHub (Oct 28, 2025):

Does librespot retry key requests on error? I am still getting the same behaviour as yesterday, 1 in 4 tracks cannot be played. I haven't tested whether they are the same tracks or random ones. For example, I cannot play the track posted by OP.

<!-- gh-comment-id:3457475253 --> @devgianlu commented on GitHub (Oct 28, 2025): Does librespot retry key requests on error? I am still getting the same behaviour as yesterday, 1 in 4 tracks cannot be played. I haven't tested whether they are the same tracks or random ones. For example, I cannot play the track posted by OP.
Author
Owner

@kingosticks commented on GitHub (Oct 29, 2025):

Does librespot retry key requests on error?

No, no retry, I think it carries on without a key in case it's a file without encryption (I don't know if that's ever available for audio tracks).

I don't think I can play the OP's track directly, for me (in the UK) it resolves to spotify:track:6xoKWTiw0jVO3IvEKLxMSs with fileId 2e205eff999ed319b318c8ce1d4e94083fd2d2a4 for OGG_VORBIS_320.

With librespot I can play that consistently, like all other tracks.

[2025-10-29T11:56:18Z DEBUG librespot_playback::player] command=Load(SpotifyUri("spotify:track:0ffiD4SYlHEifVwzBdPqd7"), true, 0)
...
[2025-10-29T11:56:18Z INFO  librespot_playback::player] Loading <god's chariots> with Spotify URI <spotify:track:6xoKWTiw0jVO3IvEKLxMSs>
[2025-10-29T11:56:18Z DEBUG librespot_playback::player] Selecting OGG_VORBIS_320 for file_id 2e205eff999ed319b318c8ce1d4e94083fd2d2a4
[2025-10-29T11:56:18Z DEBUG librespot_audio::fetch] Downloading file 2e205eff999ed319b318c8ce1d4e94083fd2d2a4
[2025-10-29T11:56:18Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2025-10-29T11:56:18Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/storage-resolve/files/audio/interactive/2e205eff999ed319b318c8ce1d4e94083fd2d2a4?product=0&country=GB&salt=3806513499
[2025-10-29T11:56:19Z INFO  librespot_playback::player] <god's chariots> (183506 ms) loaded

I couldn't get go-librespot to work under the environment I have here (WSL2 and a corporate firewall). My Windows desktop Spotify client disconnects after the first play attempt. I have no idea why (other than it's not related to any key issues).

<!-- gh-comment-id:3461161331 --> @kingosticks commented on GitHub (Oct 29, 2025): > Does librespot retry key requests on error? No, no retry, I think it carries on without a key in case it's a file without encryption (I don't know if that's ever available for audio tracks). I don't think I can play the OP's track directly, for me (in the UK) it resolves to spotify:track:6xoKWTiw0jVO3IvEKLxMSs with fileId 2e205eff999ed319b318c8ce1d4e94083fd2d2a4 for OGG_VORBIS_320. With librespot I can play that consistently, like all other tracks. ``` [2025-10-29T11:56:18Z DEBUG librespot_playback::player] command=Load(SpotifyUri("spotify:track:0ffiD4SYlHEifVwzBdPqd7"), true, 0) ... [2025-10-29T11:56:18Z INFO librespot_playback::player] Loading <god's chariots> with Spotify URI <spotify:track:6xoKWTiw0jVO3IvEKLxMSs> [2025-10-29T11:56:18Z DEBUG librespot_playback::player] Selecting OGG_VORBIS_320 for file_id 2e205eff999ed319b318c8ce1d4e94083fd2d2a4 [2025-10-29T11:56:18Z DEBUG librespot_audio::fetch] Downloading file 2e205eff999ed319b318c8ce1d4e94083fd2d2a4 [2025-10-29T11:56:18Z INFO librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point [2025-10-29T11:56:18Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/storage-resolve/files/audio/interactive/2e205eff999ed319b318c8ce1d4e94083fd2d2a4?product=0&country=GB&salt=3806513499 [2025-10-29T11:56:19Z INFO librespot_playback::player] <god's chariots> (183506 ms) loaded ``` I couldn't get go-librespot to work under the environment I have here (WSL2 and a corporate firewall). My Windows desktop Spotify client disconnects after the first play attempt. I have no idea why (other than it's not related to any key issues).
Author
Owner

@darionis commented on GitHub (Nov 10, 2025):

I am facing the same issue, "aes key code 1". I can play one song, no problem, but then playing stops with the "aes key" error.

I use go-librespot on RPi (OSMC) to connect and controll it form laptop or phone. It worked perfectly until a month ago.

DEBU[0362] loading track (paused: false, position: 1ms)  uri="spotify:track:65nl6oja2GEOJYRmVSB2lL"
DEBU[0362] put connect state because PLAYER_STATE_CHANGED 
TRAC[0362] voiding websocket event: will_play           
DEBU[0362] selected format OGG_VORBIS_160 (2c424e24c28779dd0054886e5445fd7a4d486e26)  uri="spotify:track:65nl6oja2GEOJYRmVSB2lL"
DEBU[0362] requested aes key for file 2c424e24c28779dd0054886e5445fd7a4d486e26, gid: 65nl6oja2GEOJYRmVSB2lL 
ERRO[0362] failed advancing to next track                error="failed loading current track (advance to spotify:track:65nl6oja2GEOJYRmVSB2lL): failed creating stream for spotify:track:65nl6oja2GEOJYRmVSB2lL: failed retrieving audio key: failed retrieving aes key with code 1"
TRAC[0362] voiding websocket event: stopped       

When I restart go-librespot, I can play the very same song which failed minute ago.

<!-- gh-comment-id:3511253082 --> @darionis commented on GitHub (Nov 10, 2025): I am facing the same issue, "aes key code 1". I can play one song, no problem, but then playing stops with the "aes key" error. I use go-librespot on RPi (OSMC) to connect and controll it form laptop or phone. It worked perfectly until a month ago. ``` DEBU[0362] loading track (paused: false, position: 1ms) uri="spotify:track:65nl6oja2GEOJYRmVSB2lL" DEBU[0362] put connect state because PLAYER_STATE_CHANGED TRAC[0362] voiding websocket event: will_play DEBU[0362] selected format OGG_VORBIS_160 (2c424e24c28779dd0054886e5445fd7a4d486e26) uri="spotify:track:65nl6oja2GEOJYRmVSB2lL" DEBU[0362] requested aes key for file 2c424e24c28779dd0054886e5445fd7a4d486e26, gid: 65nl6oja2GEOJYRmVSB2lL ERRO[0362] failed advancing to next track error="failed loading current track (advance to spotify:track:65nl6oja2GEOJYRmVSB2lL): failed creating stream for spotify:track:65nl6oja2GEOJYRmVSB2lL: failed retrieving audio key: failed retrieving aes key with code 1" TRAC[0362] voiding websocket event: stopped ``` When I restart go-librespot, I can play the very same song which failed minute ago.
Author
Owner

@tooxo commented on GitHub (Nov 10, 2025):

One possible mitigation i would propose is just skipping those songs for now, keeping an error in the logs.

<!-- gh-comment-id:3512677932 --> @tooxo commented on GitHub (Nov 10, 2025): One possible mitigation i would propose is just skipping those songs for now, keeping an error in the logs.
Author
Owner

@tagdara commented on GitHub (Nov 11, 2025):

Seeing this repeatedly on my system. I use a python app based on Tekore to feed librespot-go tracks and have not made it 10 songs in a row for the last couple days without this error. Skipping once or twice jumpstarts it for a bit.

<!-- gh-comment-id:3518257683 --> @tagdara commented on GitHub (Nov 11, 2025): Seeing this repeatedly on my system. I use a python app based on Tekore to feed librespot-go tracks and have not made it 10 songs in a row for the last couple days without this error. Skipping once or twice jumpstarts it for a bit.
Author
Owner

@kleinnic74 commented on GitHub (Nov 11, 2025):

I've had the same problem and could not play any song, but after changing "flac_enabled: true" to "flac_enabled: false" in the config, songs started playing again without problem. No songs skipped so far.

<!-- gh-comment-id:3518835805 --> @kleinnic74 commented on GitHub (Nov 11, 2025): I've had the same problem and could not play any song, but after changing "flac_enabled: true" to "flac_enabled: false" in the config, songs started playing again without problem. No songs skipped so far.
Author
Owner

@NezarecSh commented on GitHub (Nov 15, 2025):

I've had the same problem and could not play any song, but after changing "flac_enabled: true" to "flac_enabled: false" in the config, songs started playing again without problem. No songs skipped so far.

can you confirm this is still working?

edit: i've tried to do that on my RPI 4 and it didn't work for me.

<!-- gh-comment-id:3536526439 --> @NezarecSh commented on GitHub (Nov 15, 2025): > I've had the same problem and could not play any song, but after changing "flac_enabled: true" to "flac_enabled: false" in the config, songs started playing again without problem. No songs skipped so far. can you confirm this is still working? edit: i've tried to do that on my RPI 4 and it didn't work for me.
Author
Owner

@NezarecSh commented on GitHub (Nov 15, 2025):

I'm not sure if it matters but I noticed its related to albums. if a song isn't playing, then the whole album it was released in won't play either and give this error:

time="2025-11-15T14:36:58Z" level=warning msg="failed handling dealer request" error="failed loading current track (load context): failed creating stream for spotify:track:6cHYuLc3W90bBlpgCQv2bs: failed retrieving audio key: failed retrieving aes key with code 1"

<!-- gh-comment-id:3536549975 --> @NezarecSh commented on GitHub (Nov 15, 2025): I'm not sure if it matters but I noticed its related to albums. if a song isn't playing, then the whole album it was released in won't play either and give this error: `time="2025-11-15T14:36:58Z" level=warning msg="failed handling dealer request" error="failed loading current track (load context): failed creating stream for spotify:track:6cHYuLc3W90bBlpgCQv2bs: failed retrieving audio key: failed retrieving aes key with code 1"`
Author
Owner

@kleinnic74 commented on GitHub (Nov 17, 2025):

I've had the same problem and could not play any song, but after changing "flac_enabled: true" to "flac_enabled: false" in the config, songs started playing again without problem. No songs skipped so far.

can you confirm this is still working?

edit: i've tried to do that on my RPI 4 and it didn't work for me.

I checked again today and consistently got the "failed retrieving aes ke with code 1" for every song when enabling flac. For the same songs, when disabling flac, things worked smoothly.

However, I do get the error every now and then also with Ogg Vorbis songs, but could not recognise a pattern.

<!-- gh-comment-id:3543667602 --> @kleinnic74 commented on GitHub (Nov 17, 2025): > > I've had the same problem and could not play any song, but after changing "flac_enabled: true" to "flac_enabled: false" in the config, songs started playing again without problem. No songs skipped so far. > > can you confirm this is still working? > > edit: i've tried to do that on my RPI 4 and it didn't work for me. I checked again today and consistently got the "failed retrieving aes ke with code 1" for every song when enabling flac. For the same songs, when disabling flac, things worked smoothly. However, I do get the error every now and then also with Ogg Vorbis songs, but could not recognise a pattern.
Author
Owner

@tagdara commented on GitHub (Nov 26, 2025):

I added a retry in my player when receiving a 500 error on the websocket as a work-around, but typically once a song fails, the retries don't work either. Skipping to another song until there's no 500 is the only way I've been able to keep my music playing. Here's what the librespot-go (running in docker) log looks like.

Combined with the volume level problems in my other issue, it's in pretty rough shape and requires a lot of babysitting now.

time="2025-11-26T19:28:56Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:29LWikznvs4m7XSy10MwJl: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:28:57Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:29LWikznvs4m7XSy10MwJl: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:28:57Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:29LWikznvs4m7XSy10MwJl: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:28:58Z" level=info msg="loaded track \"Eyes Closed\" (paused: false, position: 0ms, duration: 200026ms, prefetched: false)" uri="spotify:track:7xDd7gl6AGgpiOz5trz4dM"
time="2025-11-26T19:32:17Z" level=info msg="loaded track \"Eyes Closed\" (paused: true, position: 0ms, duration: 200026ms, prefetched: false)" uri="spotify:track:7xDd7gl6AGgpiOz5trz4dM"
time="2025-11-26T19:32:17Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:32:18Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:32:18Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:32:19Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-11-26T19:32:19Z" level=info msg="loaded track \"Disco Gettin' Jacked - Original Mix\" (paused: false, position: 0ms, duration: 374736ms, prefetched: false)" uri="spotify:track:2uXSVtE7MVjMcco5VCa36q"
time="2025-11-26T19:38:35Z" level=info msg="loaded track \"Disco Gettin' Jacked - Original Mix\" (paused: true, position: 0ms, duration: 374736ms, prefetched: false)" uri="spotify:track:2uXSVtE7MVjMcco5VCa36q"
time="2025-11-26T19:38:35Z" level=info msg="loaded track \"Party in Central Park (feat. Dr. Luke)\" (paused: false, position: 0ms, duration: 244826ms, prefetched: false)" uri="spotify:track:7pyMfnG1QbaMfwwSEdaSjY"
<!-- gh-comment-id:3582982068 --> @tagdara commented on GitHub (Nov 26, 2025): I added a retry in my player when receiving a 500 error on the websocket as a work-around, but typically once a song fails, the retries don't work either. Skipping to another song until there's no 500 is the only way I've been able to keep my music playing. Here's what the librespot-go (running in docker) log looks like. Combined with the volume level problems in my other issue, it's in pretty rough shape and requires a lot of babysitting now. ``` time="2025-11-26T19:28:56Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:29LWikznvs4m7XSy10MwJl: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:28:57Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:29LWikznvs4m7XSy10MwJl: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:28:57Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:29LWikznvs4m7XSy10MwJl: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:28:58Z" level=info msg="loaded track \"Eyes Closed\" (paused: false, position: 0ms, duration: 200026ms, prefetched: false)" uri="spotify:track:7xDd7gl6AGgpiOz5trz4dM" time="2025-11-26T19:32:17Z" level=info msg="loaded track \"Eyes Closed\" (paused: true, position: 0ms, duration: 200026ms, prefetched: false)" uri="spotify:track:7xDd7gl6AGgpiOz5trz4dM" time="2025-11-26T19:32:17Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:32:18Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:32:18Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:32:19Z" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4zxFmAlT6ovJIQKX21nIBF: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-11-26T19:32:19Z" level=info msg="loaded track \"Disco Gettin' Jacked - Original Mix\" (paused: false, position: 0ms, duration: 374736ms, prefetched: false)" uri="spotify:track:2uXSVtE7MVjMcco5VCa36q" time="2025-11-26T19:38:35Z" level=info msg="loaded track \"Disco Gettin' Jacked - Original Mix\" (paused: true, position: 0ms, duration: 374736ms, prefetched: false)" uri="spotify:track:2uXSVtE7MVjMcco5VCa36q" time="2025-11-26T19:38:35Z" level=info msg="loaded track \"Party in Central Park (feat. Dr. Luke)\" (paused: false, position: 0ms, duration: 244826ms, prefetched: false)" uri="spotify:track:7pyMfnG1QbaMfwwSEdaSjY" ```
Author
Owner

@dflvunoooooo commented on GitHub (Nov 28, 2025):

I am seeing this error more often over the last week too. It started with one or two songs not playing and now the biggest part of a playlist can't be played.

<!-- gh-comment-id:3590082680 --> @dflvunoooooo commented on GitHub (Nov 28, 2025): I am seeing this error more often over the last week too. It started with one or two songs not playing and now the biggest part of a playlist can't be played.
Author
Owner

@dflvunoooooo commented on GitHub (Dec 1, 2025):

I am not having this problem with the rust librespot version.

<!-- gh-comment-id:3598916008 --> @dflvunoooooo commented on GitHub (Dec 1, 2025): I am not having this problem with the rust librespot version.
Author
Owner

@iVolt1 commented on GitHub (Dec 1, 2025):

I am seeing this too on new a build from the master today. After the track had the error I skipped to the next track which played ok. I then skipped back twice to the track that errored and it errored again.

time="2025-12-01T15:33:50-06:00" level=debug msg="prefetching next track" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:33:50-06:00" level=debug msg="selected format OGG_VORBIS_320 (178127bbd241b8fa3d310a73d55acda3aee0789b)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:33:50-06:00" level=debug msg="requested aes key for file 178127bbd241b8fa3d310a73d55acda3aee0789b, gid: 0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:33:50-06:00" level=warning msg="failed prefetching track stream" error="failed retrieving audio key: failed retrieving aes key with code 1" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:34:20-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:34:20-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:34:20-06:00" level=debug msg="selected format OGG_VORBIS_320 (178127bbd241b8fa3d310a73d55acda3aee0789b)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:34:20-06:00" level=debug msg="requested aes key for file 178127bbd241b8fa3d310a73d55acda3aee0789b, gid: 0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:34:20-06:00" level=error msg="failed advancing to next track" error="failed loading current track (advance to spotify:track:0A31i51V3omHTJMDCJxDfh): failed creating stream for spotify:track:0A31i51V3omHTJMDCJxDfh: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-12-01T15:40:45-06:00" level=debug msg="handling skip_next player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a"
time="2025-12-01T15:40:45-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:40:46-06:00" level=debug msg="selected format OGG_VORBIS_320 (4697ec78dd4e79932eb577d70735db39f436fb4d)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="requested aes key for file 4697ec78dd4e79932eb577d70735db39f436fb4d, gid: 1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="fetched first chunk of 21, total size is 10660155 bytes" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="Sending metadata: Look Around by Them in Uniform (artwork: 168750 bytes, position: 408ms)"
time="2025-12-01T15:40:46-06:00" level=info msg="loaded track \"Look Around\" (paused: false, position: 0ms, duration: 273882ms, prefetched: false)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:40:46-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:40:46-06:00" level=debug msg="sending successful reply for dealer request"
time="2025-12-01T15:40:46-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:40:57-06:00" level=debug msg="fetched chunk 4/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:06-06:00" level=debug msg="handling skip_prev player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a"
time="2025-12-01T15:41:06-06:00" level=debug msg="seek track to 0ms"
time="2025-12-01T15:41:07-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:41:07-06:00" level=debug msg="sending successful reply for dealer request"
time="2025-12-01T15:41:08-06:00" level=debug msg="handling skip_prev player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a"
time="2025-12-01T15:41:08-06:00" level=debug msg="skip previous track"
time="2025-12-01T15:41:08-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:41:08-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:41:08-06:00" level=debug msg="selected format OGG_VORBIS_320 (178127bbd241b8fa3d310a73d55acda3aee0789b)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:41:08-06:00" level=debug msg="requested aes key for file 178127bbd241b8fa3d310a73d55acda3aee0789b, gid: 0A31i51V3omHTJMDCJxDfh"
time="2025-12-01T15:41:08-06:00" level=warning msg="failed handling dealer request" error="failed loading current track (skip prev): failed creating stream for spotify:track:0A31i51V3omHTJMDCJxDfh: failed retrieving audio key: failed retrieving aes key with code 1"
time="2025-12-01T15:41:16-06:00" level=debug msg="handling pause player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a"
time="2025-12-01T15:41:16-06:00" level=warning msg="failed handling dealer request" error="no primary stream"
time="2025-12-01T15:41:17-06:00" level=debug msg="handling pause player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a"
time="2025-12-01T15:41:17-06:00" level=warning msg="failed handling dealer request" error="no primary stream"
time="2025-12-01T15:41:18-06:00" level=debug msg="handling skip_next player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a"
time="2025-12-01T15:41:18-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:41:18-06:00" level=debug msg="selected format OGG_VORBIS_320 (4697ec78dd4e79932eb577d70735db39f436fb4d)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="requested aes key for file 4697ec78dd4e79932eb577d70735db39f436fb4d, gid: 1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="fetched first chunk of 21, total size is 10660155 bytes" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:18-06:00" level=debug msg="Sending metadata: Look Around by Them in Uniform (artwork: 168750 bytes, position: 353ms)"
time="2025-12-01T15:41:18-06:00" level=info msg="loaded track \"Look Around\" (paused: false, position: 0ms, duration: 273882ms, prefetched: false)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG"
time="2025-12-01T15:41:19-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
time="2025-12-01T15:41:19-06:00" level=debug msg="sending successful reply for dealer request"
time="2025-12-01T15:41:19-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
<!-- gh-comment-id:3599084539 --> @iVolt1 commented on GitHub (Dec 1, 2025): I am seeing this too on new a build from the master today. After the track had the error I skipped to the next track which played ok. I then skipped back twice to the track that errored and it errored again. ``` time="2025-12-01T15:33:50-06:00" level=debug msg="prefetching next track" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:33:50-06:00" level=debug msg="selected format OGG_VORBIS_320 (178127bbd241b8fa3d310a73d55acda3aee0789b)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:33:50-06:00" level=debug msg="requested aes key for file 178127bbd241b8fa3d310a73d55acda3aee0789b, gid: 0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:33:50-06:00" level=warning msg="failed prefetching track stream" error="failed retrieving audio key: failed retrieving aes key with code 1" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:34:20-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:34:20-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:34:20-06:00" level=debug msg="selected format OGG_VORBIS_320 (178127bbd241b8fa3d310a73d55acda3aee0789b)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:34:20-06:00" level=debug msg="requested aes key for file 178127bbd241b8fa3d310a73d55acda3aee0789b, gid: 0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:34:20-06:00" level=error msg="failed advancing to next track" error="failed loading current track (advance to spotify:track:0A31i51V3omHTJMDCJxDfh): failed creating stream for spotify:track:0A31i51V3omHTJMDCJxDfh: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-12-01T15:40:45-06:00" level=debug msg="handling skip_next player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a" time="2025-12-01T15:40:45-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:40:46-06:00" level=debug msg="selected format OGG_VORBIS_320 (4697ec78dd4e79932eb577d70735db39f436fb4d)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="requested aes key for file 4697ec78dd4e79932eb577d70735db39f436fb4d, gid: 1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="fetched first chunk of 21, total size is 10660155 bytes" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="Sending metadata: Look Around by Them in Uniform (artwork: 168750 bytes, position: 408ms)" time="2025-12-01T15:40:46-06:00" level=info msg="loaded track \"Look Around\" (paused: false, position: 0ms, duration: 273882ms, prefetched: false)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:40:46-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:40:46-06:00" level=debug msg="sending successful reply for dealer request" time="2025-12-01T15:40:46-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:40:57-06:00" level=debug msg="fetched chunk 4/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:06-06:00" level=debug msg="handling skip_prev player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a" time="2025-12-01T15:41:06-06:00" level=debug msg="seek track to 0ms" time="2025-12-01T15:41:07-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:41:07-06:00" level=debug msg="sending successful reply for dealer request" time="2025-12-01T15:41:08-06:00" level=debug msg="handling skip_prev player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a" time="2025-12-01T15:41:08-06:00" level=debug msg="skip previous track" time="2025-12-01T15:41:08-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:41:08-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:41:08-06:00" level=debug msg="selected format OGG_VORBIS_320 (178127bbd241b8fa3d310a73d55acda3aee0789b)" uri="spotify:track:0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:41:08-06:00" level=debug msg="requested aes key for file 178127bbd241b8fa3d310a73d55acda3aee0789b, gid: 0A31i51V3omHTJMDCJxDfh" time="2025-12-01T15:41:08-06:00" level=warning msg="failed handling dealer request" error="failed loading current track (skip prev): failed creating stream for spotify:track:0A31i51V3omHTJMDCJxDfh: failed retrieving audio key: failed retrieving aes key with code 1" time="2025-12-01T15:41:16-06:00" level=debug msg="handling pause player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a" time="2025-12-01T15:41:16-06:00" level=warning msg="failed handling dealer request" error="no primary stream" time="2025-12-01T15:41:17-06:00" level=debug msg="handling pause player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a" time="2025-12-01T15:41:17-06:00" level=warning msg="failed handling dealer request" error="no primary stream" time="2025-12-01T15:41:18-06:00" level=debug msg="handling skip_next player command from ade581dcecdcfa8e0dd37a10c599827c4e8f4d6a" time="2025-12-01T15:41:18-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:41:18-06:00" level=debug msg="selected format OGG_VORBIS_320 (4697ec78dd4e79932eb577d70735db39f436fb4d)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="requested aes key for file 4697ec78dd4e79932eb577d70735db39f436fb4d, gid: 1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="fetched first chunk of 21, total size is 10660155 bytes" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:18-06:00" level=debug msg="Sending metadata: Look Around by Them in Uniform (artwork: 168750 bytes, position: 353ms)" time="2025-12-01T15:41:18-06:00" level=info msg="loaded track \"Look Around\" (paused: false, position: 0ms, duration: 273882ms, prefetched: false)" uri="spotify:track:1sQVBw9oGkNoiE4qYEpDrG" time="2025-12-01T15:41:19-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" time="2025-12-01T15:41:19-06:00" level=debug msg="sending successful reply for dealer request" time="2025-12-01T15:41:19-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" ```
Author
Owner

@tooxo commented on GitHub (Dec 1, 2025):

What i found interesting in comparison to the librespot client:

  • librespot does not request the AUDIO_FILES extension kind at all, it does request the TRACK_V4 endpoint a second time, with another track-id leading to the same song (librespot does also receive no audio files in return on the first request, but does on the second one)
  • this results in go-librespot getting (and therefore selecting) other file ids than librespot, what i would assume leads to the audio key lookup failing
  • (probably not relevant: librespot also sets these params at every extended-metadata request product=0, country=[country], salt=[random value])

Update:
Looking inside the debugger, it seems like go-librespot does not care if the song is not allowed to be played anywhere as seen here:
Image

So the solution seems to be to request the track listed inside the "alternative" field of the extended-metadata response, which in the case of the track listed in the response above already contains the working file ids. This seems to have been removed in c7a5da1e9a, maybe @devgianlu can explain why.

<!-- gh-comment-id:3599449993 --> @tooxo commented on GitHub (Dec 1, 2025): What i found interesting in comparison to the librespot client: * librespot does not request the AUDIO_FILES extension kind at all, it does request the TRACK_V4 endpoint a second time, with another track-id leading to the same song (librespot does also receive no audio files in return on the first request, but does on the second one) * this results in go-librespot getting (and therefore selecting) other file ids than librespot, what i would assume leads to the audio key lookup failing * (probably not relevant: librespot also sets these params at every extended-metadata request product=0, country=[country], salt=[random value]) Update: Looking inside the debugger, it seems like go-librespot does not care if the song is not allowed to be played anywhere as seen here: <img width="711" height="250" alt="Image" src="https://github.com/user-attachments/assets/59a9cbd9-f512-4394-bfb7-ef815b071dac" /> So the solution seems to be to request the track listed inside the "alternative" field of the extended-metadata response, which in the case of the track listed in the response above already contains the working file ids. This seems to have been removed in c7a5da1e9abe3e9872adddb0160ad1d0447cb5dc, maybe @devgianlu can explain why.
Author
Owner

@devgianlu commented on GitHub (Dec 2, 2025):

Thank you @tooxo for the investigation, that seems to be the culprit indeed. I filed a PR which makes the tracks playable again, can you give it a try?

<!-- gh-comment-id:3600922491 --> @devgianlu commented on GitHub (Dec 2, 2025): Thank you @tooxo for the investigation, that seems to be the culprit indeed. I filed a PR which makes the tracks playable again, can you give it a try?
Author
Owner

@devgianlu commented on GitHub (Dec 2, 2025):

I've merged the fix, please let me know if the issue persists.

<!-- gh-comment-id:3601531814 --> @devgianlu commented on GitHub (Dec 2, 2025): I've merged the fix, please let me know if the issue persists.
Author
Owner

@tooxo commented on GitHub (Dec 2, 2025):

I've merged the fix, please let me know if the issue persists.

Was just able to test it, seems to at least work with the tracks that did not yesterday.

<!-- gh-comment-id:3601609282 --> @tooxo commented on GitHub (Dec 2, 2025): > I've merged the fix, please let me know if the issue persists. Was just able to test it, seems to at least work with the tracks that did not yesterday.
Author
Owner

@devgianlu commented on GitHub (Dec 2, 2025):

This track does not seem to play, even with the changes: https://open.spotify.com/track/79L8Au1ipSKjIXK2ZggRfP

<!-- gh-comment-id:3601663357 --> @devgianlu commented on GitHub (Dec 2, 2025): This track does not seem to play, even with the changes: https://open.spotify.com/track/79L8Au1ipSKjIXK2ZggRfP
Author
Owner

@NezarecSh commented on GitHub (Dec 2, 2025):

This track does not seem to play, even with the changes: https://open.spotify.com/track/79L8Au1ipSKjIXK2ZggRfP

This track does not seem to exist on spotify. I couldn't find it at least. I think it's unrelated to go-librespot

Edit: the entire album (Godfather) doesn't seem to exist lol

<!-- gh-comment-id:3601777572 --> @NezarecSh commented on GitHub (Dec 2, 2025): > This track does not seem to play, even with the changes: https://open.spotify.com/track/79L8Au1ipSKjIXK2ZggRfP This track does not seem to exist on spotify. I couldn't find it at least. I think it's unrelated to go-librespot Edit: the entire album (Godfather) doesn't seem to exist lol
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/go-librespot#150
No description provided.