Can't play short files: "Unable to load encrypted file"

[Malvineous]

If you try to play a short file (not sure of the exact length, but seems like under 30 seconds), playback fails:

TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
DEBUG librespot_playback::player] command=Load(SpotifyId { id: 301932663658771966891455576440240138600, audio_type: Track }, true, 0)
TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
INFO  librespot_playback::player] Loading <Her Majesty - Remastered 2009> with Spotify URI <spotify:track:6UCFZ9ZOFRxK8oak7MdPZu>
DEBUG librespot_audio::fetch] Downloading file 6dba450723dfdf967aa3740beeca4d73adde7bca
ERROR librespot_core::channel] channel error: 2 0
ERROR librespot_playback::player] Unable to load encrypted file.
WARN  librespot_playback::player] Unable to load <SpotifyId { id: 301932663658771966891455576440240138600, audio_type: Track }>
Skipping to next track
DEBUG librespot_connect::spirc] At track 6 of 7 <"spotify:playlist:3NebgOp0IPF6BBAa4QynYy"> update [true]
TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
DEBUG librespot_playback::player] command=Load(SpotifyId { id: 266252029018687294844893778780865354245, audio_type: Track }, true, 0)
TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
INFO  librespot_playback::player] Loading <Yeah - Remastered 2011> with Spotify URI <spotify:track:65YeIE3Y4YBNLnXcpVZz1P>
DEBUG librespot_audio::fetch] Downloading file f284aab8b539754b5c6c04eaa182a95d2258ad93
ERROR librespot_core::channel] channel error: 2 0
ERROR librespot_playback::player] Unable to load encrypted file.
WARN  librespot_playback::player] Unable to load <SpotifyId { id: 266252029018687294844893778780865354245, audio_type: Track }>
Skipping to next track
DEBUG librespot_connect::spirc] At track 7 of 7 <"spotify:playlist:3NebgOp0IPF6BBAa4QynYy"> update [true]
TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]

Songs of 40 seconds or longer on the same albums seem to load and play fine, and the failing short songs also play fine through the web browser client.

Here is a sample playlist with only songs that fail in librespot.

[michaelherger]

I've seen similar reports where people claim that this was a recent change in behaviour (not librespot release related). As if something on Spotify's end had changed, causing this.

They also say that the threshold for the track length depends on the bitrate used. Eg. at 96kbps you'd need at least 1:30 to play successfully (https://forums.slimdevices.com/showthread.php?112638-Spotty-Crashing-Help&p=982803&viewfull=1#post982803)

[jpochyla]

Looks like that after the first request on the audio file channel a message with CHANNEL_ERROR (0x0a) command and error type 0x00 is received, and the channel gets closed and stays silent after that. I've tried to lower the initial request size, but it didn't help.

[michaelherger]

From above linked thread:

This all started in the thread where @laz was having problems playing tracks from "Pink Flag". It seems that tracks shorter than around 25 seconds fail at 320kbps while this increases to around 1:40 at 96kbps when played from within LMS. I remember playing the first track on the Billy Eilish album which is 15 seconds a few months ago so this is a relatively new issue.

[sashahilton00]

I wonder if it is an issue with our chunk size that we try to download. iirc the client chooses the chunk range so it may be that we have quite a large range per chunk, which causes issues for songs with a size less than that of a single chunk.

Possibly something to do with this: const MINIMUM_DOWNLOAD_SIZE: usize = 1024 * 16; though would need to explore further to see if this is responsible for what I think it is.

[jpochyla]

@sashahilton00 I've tested first chunk requests for 4..=1024*16 bytes and unfortunately it does not help. Shifting the initial offset above 0 also has no effect. What about the other content of the chunk request? There's a couple of magic numbers: https://github.com/librespot-org/librespot/blob/dev/audio/src/fetch.rs#L480-L488

[devgianlu]

There's a couple of magic numbers: https://github.com/librespot-org/librespot/blob/dev/audio/src/fetch.rs#L480-L488

I once tried tweaking them, they seem to do nothing.

[sashahilton00]

It's been a very long time since I looked at the audio download logic, and I can't remember if we moved to HTTP retrieval or if we still pull the files via Mercury. If it is indeed a size issue, the client sends an options header before downloading files, my guess is that header returns the file size, which is used to work out the chunk size used for download.

[jpochyla]

It's been a very long time since I looked at the audio download logic, and I can't remember if we moved to HTTP retrieval or if we still pull the files via Mercury.

librespot is still using Mercury channels for downloading audio. Even if we move to HTTPS transport, the audio keys would still need to be fetched over Mercury, is that correct?

[devgianlu]

Even if we move to HTTPS transport, the audio keys would still need to be fetched over Mercury, is that correct?

Yes, the audio key system is still the same.

[Malvineous]

FYI I am still getting occasional channel errors but I seem to be able to play short songs again now.

[michaelherger]

I doubt this is a coincidence, but one of my users reported a very similar observation only minutes after you. All the short tracks I've tested indeed do play again.

[Malvineous]

Interesting! Unfortunately a bunch of other songs now fail for me (#519) but at least all the short ones work...

[wlonkly]

Another data point, if it's helpful -- I've had my librespot (via raspotify) stopping on every 2nd or 3rd track today.

[2020-08-15T17:25:39Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 216002112650113847186430071822932201072, audio_type: Track })
[2020-08-15T17:25:39Z DEBUG librespot_playback::player] Preloading track
[2020-08-15T17:25:39Z INFO  librespot_playback::player] Loading <Johnny> with Spotify URI <spotify:track:4WDtGj1M2HFlcjvYIiRFug>
[2020-08-15T17:25:39Z DEBUG librespot_audio::fetch] Downloading file 31546647b10b4534c954dc3de059d4ca3bd6c674
[2020-08-15T17:25:39Z ERROR librespot_core::channel] channel error: 2 0
[2020-08-15T17:25:39Z ERROR librespot_playback::player] Unable to load encrypted file.
[2020-08-15T17:25:48Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
[2020-08-15T17:26:09Z DEBUG librespot_connect::spirc] At track 2 of 80 <"spotify:user:spotify:playlist:37i9dQZF1DX5Q5wA1hY6bS"> update [false]
[2020-08-15T17:26:09Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-08-15T17:26:09Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 216002112650113847186430071822932201072, audio_type: Track }, true, 0)
[2020-08-15T17:26:09Z TRACE librespot_playback::player] == Stopping sink ==
[2020-08-15T17:26:09Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-08-15T17:26:09Z INFO  librespot_playback::player] Loading <Johnny> with Spotify URI <spotify:track:4WDtGj1M2HFlcjvYIiRFug>
[2020-08-15T17:26:09Z DEBUG librespot_audio::fetch] Downloading file 31546647b10b4534c954dc3de059d4ca3bd6c674
[2020-08-15T17:26:10Z ERROR librespot_core::channel] channel error: 2 0
[2020-08-15T17:26:10Z ERROR librespot_playback::player] Unable to load encrypted file.
[2020-08-15T17:26:10Z WARN  librespot_connect::spirc] The player has stopped unexpectedly.
[2020-08-15T17:26:10Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusStop]

That track is this which is 4:00 so not a "short track".

Build:

librespot (raspotify v0.14.0) 6aac8a6 (2020-07-24). Built on 2020-07-26. Build ID: wPNyqn0m

A few more failing tracks:

[2020-08-15T16:07:21Z INFO  librespot_playback::player] Loading <PLACES> with Spotify URI <spotify:track:3eSmjY0PxxTlX6UxRDKaul>
[2020-08-15T16:24:15Z INFO  librespot_playback::player] Loading <Pink & Blue> with Spotify URI <spotify:track:1TJqHWEHHQ7Z5mJ0P6rXqq>
[2020-08-15T16:26:13Z INFO  librespot_playback::player] Loading <Here We Are Again> with Spotify URI <spotify:track:3CLsZEY8QC4ZTBJGF47sGp>
[2020-08-15T17:13:04Z INFO  librespot_playback::player] Loading <It Never Rains> with Spotify URI <spotify:track:67URyvNo0ymOlShJB9JclN>
[2020-08-15T17:15:07Z INFO  librespot_playback::player] Loading <Amadeus> with Spotify URI <spotify:track:4F9jpNQDKRFoyM4Ebpni6S>

[Malvineous]

@wlonkly Looks like you're encountering issue #519 as well

[gnosek]

Another data point, a 3m20s track, reliably failing to play (for me at least):

sie 16 14:09:59 hex librespot[3124]: [2020-08-16T12:09:59Z INFO  librespot_playback::player] Loading <My Quarantine> with Spotify URI <spotify:track:1t9WkJQ4CAUExxwjAXujZa>
sie 16 14:09:59 hex librespot[3124]: [2020-08-16T12:09:59Z ERROR librespot_core::channel] channel error: 2 0
sie 16 14:09:59 hex librespot[3124]: [2020-08-16T12:09:59Z ERROR librespot_playback::player] Unable to load encrypted file.
sie 16 14:09:59 hex librespot[3124]: [2020-08-16T12:09:59Z WARN  librespot_playback::player] Unable to load <SpotifyId { id: 64215476694544839543753118473173377052, audio_type: Track }>
sie 16 14:09:59 hex librespot[3124]: Skipping to next track

[wlonkly]

@wlonkly Looks like you're encountering issue #519 as well

Hah, I looked at both and thought "Well, what are the odds of this being BOTH bugs?" and picked one. I guess the odds are higher than I thought! Followed that one too. If I knew a bit of Rust I'd dig deeper, but I don't :/

[Malvineous]

I'm going to close this issue as well as it seems there are no further problems playing short songs. Spotify seem to have rectified the problem at their end. The other issue causing problems playing longer songs is covered in #519 which is also resolved now as well.