Error reading a body from connection: end of file before message length reached

tohmais commented 1 year ago

Hi! When trying to launch spotify-launcher, the program auto-updates the spotify version. However, every time it tries to download the deb file, it errors with: Error reading a body from connection: end of file before message length reached. Below is the output of the program when this happens:

❯ spotify-launcher
[2023-09-05T01:24:40Z INFO  spotify_launcher::config] Loading configuration file at "/home/callum/.config/spotify-launcher.conf"
[2023-09-05T01:24:40Z INFO  spotify_launcher::apt] Downloading release file...
[2023-09-05T01:24:46Z INFO  spotify_launcher::apt] Downloading signature...
[2023-09-05T01:24:46Z INFO  spotify_launcher::apt] Verifying pgp signature...
[2023-09-05T01:24:46Z INFO  spotify_launcher::apt] Signature verified successfully!
[2023-09-05T01:24:46Z INFO  spotify_launcher::apt] Downloading package index...
[2023-09-05T01:24:47Z INFO  spotify_launcher::apt] Verifying with sha256sum hash...
[2023-09-05T01:24:47Z INFO  spotify_launcher::apt] Downloading deb file for "spotify-client_1.2.18.999.g9b38fc27_amd64.deb" version="spotify-client" ("1:1.2.18.999.g9b38fc27")
Error: request or response body error: error reading a body from connection: end of file before message length reached

Caused by:
    0: error reading a body from connection: end of file before message length reached
    1: end of file before message length reached

Here are the things I've tried to fix the error:

Power cycled my computer.
Uninstalled and reinstalled spotify-launcher.
Connected to a different network and tried to update.
Clearing all contents from spotify-launcher.conf.

System info: Arch Linux On Hyprland, launched via zsh using kitty.

I don't know what could be causing the error outside of the Debian package being broken right now. Thanks for creating this package!

tohmais commented 1 year ago

Ok. I just tried to install the spotify package on the AUR and it also doesn't work. This leads me to believe this is an issue with the spotify debian package itself, my network, or my system. Leaving this open in case anyone else experiences this issue.

kpcyrd commented 1 year ago

I'm suspecting it's the network, end of file before message length reached means the connection was either closed (FIN) or reset (RST).

% rm -rf ~/.local/share/spotify-launcher
% spotify-launcher --no-exec
[2023-09-05T09:25:19Z INFO  spotify_launcher::config] Loading configuration file at "/home/user/.config/spotify-launcher.conf"
[2023-09-05T09:25:19Z INFO  spotify_launcher::apt] Downloading release file...
[2023-09-05T09:25:20Z INFO  spotify_launcher::apt] Downloading signature...
[2023-09-05T09:25:20Z INFO  spotify_launcher::apt] Verifying pgp signature...
[2023-09-05T09:25:20Z INFO  spotify_launcher::apt] Signature verified successfully!
[2023-09-05T09:25:20Z INFO  spotify_launcher::apt] Downloading package index...
[2023-09-05T09:25:20Z INFO  spotify_launcher::apt] Verifying with sha256sum hash...
[2023-09-05T09:25:20Z INFO  spotify_launcher::apt] Downloading deb file for "spotify-client_1.2.18.999.g9b38fc27_amd64.deb" version="spotify-client" ("1:1.2.18.999.g9b38fc27")
[2023-09-05T09:25:32Z INFO  spotify_launcher::apt] Verifying with sha256sum hash...
[2023-09-05T09:25:32Z INFO  spotify_launcher::extract] Extracting to "/home/user/.local/share/spotify-launcher/install-new"...
[2023-09-05T09:25:35Z INFO  spotify_launcher::extract] Atomically swapping new directory at "/home/user/.local/share/spotify-launcher/install-new" with "/home/user/.local/share/spotify-launcher/install"...
[2023-09-05T09:25:35Z INFO  spotify_launcher] Skipping exec because --no-exec was used

rmullin7286 commented 1 year ago

I can confirm I'm also getting this issue since updating my arch linux system. When I run from dmenu I get a "dowloading" popup indefinitely, and when I run from the terminal I get the output @tohmais mentioned.

vprime commented 1 year ago

This seems like it's an issue on spotify's server: http://repository.spotify.com/pool/non-free/s/spotify-client/ for the time being you can continue to load spotify with spotify-launcher --skip-update

kpcyrd commented 1 year ago

I got confused for a second because Firefox warned about defunct https (after attempting to auto-upgrade the http:// link), but spotify-launcher is using http so I'm not sure why it's not working (the link opens correctly for me after clicking through the "missing https" warning and changing the url back to http://):

% spotify-launcher --check-update --no-exec -vv
[2023-09-09T11:42:40Z DEBUG spotify_launcher::config] Searching for configuration file at "/home/user/.config/spotify-launcher.conf"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::config] Found configuration file at "/home/user/.config/spotify-launcher.conf"
[2023-09-09T11:42:40Z INFO  spotify_launcher::config] Loading configuration file at "/home/user/.config/spotify-launcher.conf"
[2023-09-09T11:42:40Z DEBUG spotify_launcher] Using install path: "/home/user/.local/share/spotify-launcher/install"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::paths] Reading state file from "/home/user/.local/share/spotify-launcher/state.json"...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::paths] Loaded state: Ok(State { version: "1:1.2.20.1210.g2a8a8a57", last_update_check: SystemTime { tv_sec: 1694259751, tv_nsec: 980114310 } })
[2023-09-09T11:42:40Z INFO  spotify_launcher::apt] Downloading release file...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::http] Fetching "http://repository.spotify.com/dists/testing/Release"...
[2023-09-09T11:42:40Z DEBUG reqwest::connect] starting new connection: http://repository.spotify.com/
[2023-09-09T11:42:40Z DEBUG spotify_launcher::http] Fetched 2447 bytes
[2023-09-09T11:42:40Z INFO  spotify_launcher::apt] Downloading signature...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::http] Fetching "http://repository.spotify.com/dists/testing/Release.gpg"...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::http] Fetched 833 bytes
[2023-09-09T11:42:40Z INFO  spotify_launcher::apt] Verifying pgp signature...
[2023-09-09T11:42:40Z INFO  spotify_launcher::apt] Signature verified successfully!
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/binary-amd64/Packages" => "8037a8faf570b0d88d7c43ac2a9d52110cb0a9ab40039817bd01c7b2e59e8769"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/binary-amd64/Packages.gz" => "a79f9ddb50219abb82efb26ba14ecd0da155eee440f1548c9a6d8bf6e3d9402d"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/binary-amd64/Release" => "35876d5aa96d00b39fe3a26660a7665b4ced399a650dc3344b20dee7ad3cc766"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/binary-i386/Packages" => "497184ddb1dc525de81a1bd98ac97175b176d15ead076680d3e8d27b0b5329c8"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/binary-i386/Packages.gz" => "2654df365b0dd96a6307e6e56780815d8695ed89da547c1a6beb509035a8ddd0"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/binary-i386/Release" => "1b0d97da546cdcd460e99eaadaac929048b217a9e043a2a919a648910e8f1be4"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/source/Sources" => "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/source/Sources.gz" => "59869db34853933b239f1e2219cf7d431da006aa919635478511fabbfc8849d2"
[2023-09-09T11:42:40Z DEBUG spotify_launcher::deb] Adding file hash from release file, "non-free/source/Release" => "963be5cb6b84350b820fd4bb4ce5059bb4cbb16dcfa7614c630ded76a09155a5"
[2023-09-09T11:42:40Z INFO  spotify_launcher::apt] Downloading package index...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::http] Fetching "http://repository.spotify.com/dists/testing/non-free/binary-amd64/Packages"...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::http] Fetched 1267 bytes
[2023-09-09T11:42:40Z INFO  spotify_launcher::apt] Verifying with sha256sum hash...
[2023-09-09T11:42:40Z DEBUG spotify_launcher::apt] Parsed package index: [Pkg { package: "spotify-client", version: "1:1.2.20.1210.g2a8a8a57", filename: "pool/non-free/s/spotify-client/spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb", sha256sum: "824fdcd8a8a20fd188fe458039290bbd3a187f0d2672fd576d13fb87ef8dc48b" }]
[2023-09-09T11:42:40Z DEBUG spotify_launcher::apt] Found package: Pkg { package: "spotify-client", version: "1:1.2.20.1210.g2a8a8a57", filename: "pool/non-free/s/spotify-client/spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb", sha256sum: "824fdcd8a8a20fd188fe458039290bbd3a187f0d2672fd576d13fb87ef8dc48b" }
[2023-09-09T11:42:40Z INFO  spotify_launcher] Latest version is already installed, not updating
[2023-09-09T11:42:40Z DEBUG spotify_launcher] Updating state file
[2023-09-09T11:42:40Z DEBUG spotify_launcher] Assembled command: ["spotify", "--force-device-scale-factor=2.0"]
[2023-09-09T11:42:40Z INFO  spotify_launcher] Skipping exec because --no-exec was used

Besides me, there's also users in #32 that seem to be able to successfully download updates. FWIW, the domain resolves to 18.155.139.109 for me, which is an aws cloudfront IP address.

I also checked for "dowloading" and it seems there's no such typo in the codebase.

disconsented commented 1 year ago

For whatever reason, it appears that the Spotify server closes the connection near the end of the stream. wget will download the file successfully by retrying after it's closed, it looks like it's making a range request to fulfil the final step.

❯ wget repository.spotify.com/pool/non-free/s/spotify-client/spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb
--2023-09-11 13:10:19--  http://repository.spotify.com/pool/non-free/s/spotify-client/spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb
Resolving repository.spotify.com (repository.spotify.com)... 54.230.125.145, 54.230.125.68, 54.230.125.97, ...
Connecting to repository.spotify.com (repository.spotify.com)|54.230.125.145|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 124183006 (118M) [application/octet-stream]
Saving to: ‘spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb’

spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb        96%[=================================================================================================================>     ] 114.25M  18.9MB/s    in 7.0s

2023-09-11 13:10:26 (16.3 MB/s) - Connection closed at byte 119801104. Retrying.

--2023-09-11 13:10:27--  (try: 2)  http://repository.spotify.com/pool/non-free/s/spotify-client/spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb
Connecting to repository.spotify.com (repository.spotify.com)|54.230.125.145|:80... connected.
HTTP request sent, awaiting response... 206 Partial Content
Length: 124183006 (118M), 4381902 (4.2M) remaining [application/octet-stream]
Saving to: ‘spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb’

spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb       100%[++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++====>] 118.43M  3.58MB/s    in 1.2s

2023-09-11 13:10:29 (3.58 MB/s) - ‘spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb’ saved [124183006/124183006]

I've also just noticed that spotify-launcher --deb exists, so I've worked around this issue for now by:

# wget <url>
wget repository.spotify.com/pool/non-free/s/spotify-client/spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb
# spotify-launcher --deb <deb path>
spotify-launcher --deb spotify-client_1.2.20.1210.g2a8a8a57_amd64.deb

spotify-launcher works as expected afterwards, no need to rerun --deb (at least until the next update).

Maybe the best way to fix this is to request in chunks to work around this limitation?

mattyoung101 commented 11 months ago

Hi everyone, are there any updates on the status of this issue and the PR #34 ? The situation with Spotify is still the same, in my case, wget had to retry 7 times (!) to download the full deb. Perhaps if #34 is functional, it could possibly be merged and the code style improvements made later?

kpcyrd commented 11 months ago

The code in #34 introduces a (minor) time-of-check-time-of-use race condition, it breaks the download progress indicator, and the timeout is only applied to the code that connects, sends the http request and receives the headers, but it's unable to detect a dead connection during the download and could potentially get stuck indefinitely.

I'd rather not merge it.

mattyoung101 commented 11 months ago

No worries. Are there any plans to address this issue in a future release? I'm unfortunately not familiar enough with Rust to submit an acceptable PR at the moment.

kpcyrd commented 11 months ago

It is planned, yes. Either way, can you try running spotify-launcher --timeout 0 to check if the issue is still present then?

kpcyrd commented 11 months ago

Everybody interested in this, to help land this please test #39 and :+1: if it's working for you (and doesn't introduce any regression).

Thank you!

mattyoung101 commented 11 months ago

Thanks for the fast update! I compiled and ran #39 and it was successfully able to restart the download and update the client. I haven't seen any regressions so far, the client appears to function as normal.

It looks like it will currently retry up to 5 times before bailing? If it's not too much of a pain, this could be made reconfigurable in spotify-launcher.conf as Spotify's server seems to vary how much content it will deliver in one request.

I also tried spotify-launcher --timeout 0 on the latest Arch released version, but it wasn't able to restart the download. It quit as soon as Spotify sent the EOF.

kpcyrd commented 11 months ago

Thanks for testing, I've updated the PR so you can set download_attempts = 10 in the config, or use --download-attempts 10. Setting it to 0 does an unlimited amount of retries.

kpcyrd commented 10 months ago

This should now be fixed in 0.5.3

disconsented commented 10 months ago

Re: #34 it wasn't going to work anyway, I'd assumed that spotify's servers just wanted the file to be requested in parts, hence the chunking. I should have made it try to resume the download (like #39). I was planning to address this over the holiday break, as I'd finally have had spare time. :sweat_smile:

it breaks the download progress indicator,

Can you elaborate on this? I'd observed the progress bar updating as the chunks arrived

kpcyrd commented 10 months ago

Download::chunk is supposed to be called multiple times and return some data every time it's called. In between the calls spotify-launcher is updating the progress bar and calculate the sha256 checksum.

The patch in #34 changes this and is trying to do the entire request in one call, but I now noticed there's a let end = (begin + (self.total / 10)).min(self.total); so every chunk is trying to download 10% of the file, then update the progress bar and calculate sha256 (which is better than I initially assumed). :)

kpcyrd / spotify-launcher

Error reading a body from connection: end of file before message length reached #31