Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

signature from <package> is invalid #93

Open
naclander opened this issue Jun 2, 2022 · 27 comments
Open

signature from <package> is invalid #93

naclander opened this issue Jun 2, 2022 · 27 comments
Labels
bug Something isn't working

Comments

@naclander
Copy link

naclander commented Jun 2, 2022

Hey,

Sometimes when using flexo, I've noticed errors when my machine is validating packages in the form of:

error: <package>: signature from "<person>" is invalid
:: File /var/cache/pacman/pkg/<package>.pkg.tar.zst is corrupted (invalid or corrupted package (PGP signature)).
Do you want to delete it? [Y/n] 

Neither Y nor n fixes the problem. Clearing out the flexo cache does.
Re-downloading the archlinux-keyring also does not fix this issue.

Could this be a stale package cached in flexo somehow? Is there any mitigation for this instead of clearing out the flexo cache?

@naclander naclander changed the title signature from ____ is invalid signature from <package> is invalid Jun 2, 2022
@nroi
Copy link
Owner

nroi commented Jun 5, 2022

Edit: This is either caused by misbehaving mirrors or a bug in flexo, but I think a bug in flexo is more likely. I'm looking into this issue, but I still haven't found a way to reproduce it. If anyone stumbles on this issue, you can help me troubleshoot this issue as follows:

  1. Run the flexo-verify-package python script on the machine that's running flexo and paste the output of that script.
  2. The journalctl log (or output from docker logs if you use docker) from the time frame when the download has happened, e.g. journalctl --unit=flexo --since today.

The more output I receive, the better!


Original answer:

Could this be a stale package cached in flexo somehow?

I guess so. Probably either the package itself, or the signature (the corresponding file ending with .sig) has changed, but flexo serves the stale version from cache.

I'd like to find out if the package file (the file ending with .zst), or the signature file (ending with .sig), or both files are stale. Next time when this issue happens, can you please check which files change after you clear out the flexo cache? For example, you can run sha256sum <package>.zst and sha256sum <package>.zst.sig before clearing the flexo cache (replace <package> by any package from the error message shown by pacman), and then run the same two commands again after clearing the flexo cache to compare the checksums and see which files have changed.

Once I understand the problem, I can think of a solution.

@naclander
Copy link
Author

So it just happened again. This happens on the client machine, during the Checking package Integrity step:

error: linux-lts: signature from "Andreas Radke <andyrtr@archlinux.org>" is invalid
:: File /var/cache/pacman/pkg/linux-lts-5.15.45-1-x86_64.pkg.tar.zst is corrupted (invalid or corrupted package (PGP signature)).
Do you want to delete it? [Y/n] 
error: failed to commit transaction (invalid or corrupted package)
Errors occurred, no packages were upgraded.

The sha256sum before clearing out the package cache for all matching files is:

# sha256sum $( find ./ | grep linux-lts-5.15.45-1-x86_64.pkg.tar.zst | xargs)
d83324c5710c0b59371a53194821d31ff38a50e18af17364248add71ba011d6a  ./core/os/x86_64/linux-lts-5.15.45-1-x86_64.pkg.tar.zst.sig
bfa9b234f73416c3f7d3bb668b28d25467e1007087aadc3d8571a9c838ac316a  ./core/os/x86_64/.linux-lts-5.15.45-1-x86_64.pkg.tar.zst.sig.cfs
1fc9438708ffeabaa9a9bdb95a8cb6e8df922838f8f3f62b30c34180a0d18f8c  ./core/os/x86_64/.linux-lts-5.15.45-1-x86_64.pkg.tar.zst.cfs
1af8f502f87da3c76a3cb5e25f15a90c7ecacb42b535842889aee85077f1dbb7  ./core/os/x86_64/linux-lts-5.15.45-1-x86_64.pkg.tar.zst

I cleared out the pkg cache and restarted the flexo service, ran pacman -Sc on the client, and re-ran the update on the client.
Running the sha26sum command on the flexo server again, I see:

# sha256sum $( find ./ | grep linux-lts-5.15.45-1-x86_64.pkg.tar.zst | xargs)
d83324c5710c0b59371a53194821d31ff38a50e18af17364248add71ba011d6a  ./core/os/x86_64/linux-lts-5.15.45-1-x86_64.pkg.tar.zst.sig
bfa9b234f73416c3f7d3bb668b28d25467e1007087aadc3d8571a9c838ac316a  ./core/os/x86_64/.linux-lts-5.15.45-1-x86_64.pkg.tar.zst.sig.cfs
8bdfbbf5bdff5d2ff5863ee25ff027c3532a14b445df39de3af3e0f7265f0c35  ./core/os/x86_64/.linux-lts-5.15.45-1-x86_64.pkg.tar.zst.cfs
c825a66094df4458f410c2bf2f04753a7ed7bb4eefe896d6fbff43ed229a1737  ./core/os/x86_64/linux-lts-5.15.45-1-x86_64.pkg.tar.zst

@nroi
Copy link
Owner

nroi commented Jun 9, 2022

Ok, so the output tells us that:

  1. the signature file has not changed, neither locally nor at the mirror.
  2. the package file itself has changed both locally and at the remote mirror (this can be seen from the .cfs file, which includes the content length sent by the mirror. The .cfs file has changed, therefore, the package must also have changed at the remote mirror).

If the mirror itself served an incomplete file, this would explain this issue. Can you please run the following and show me the output?

journalctl --unit=flexo | grep Primary | tail -n20

I'd like to investigate further if any of those mirrors have issues that would explain this before ruling out that this is a bug in flexo.

If you want to try a different mirror, you can configure flexo to blacklist the previously used mirrors. Edit /etc/flexo/flexo.toml and add the mirrors to the mirrors_blacklist array. Copy the exact values that you got from the previous journalctl command, i.e., with the trailing slash. Then, remove the latency results:

sudo rm /var/cache/flexo/state/latency_test_results.json

Then, restart flexo, so it runs the latency tests again and picks up another mirror. Wait a moment until the latency tests have completed before running pacman.

@naclander
Copy link
Author

naclander commented Jun 11, 2022

# journalctl --unit=flexo | grep Primary | tail -n20
Apr 25 20:17:05 dmz-cache flexo[10406]: [2022-04-25T20:17:05.363Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:11 dmz-cache flexo[10421]: [2022-04-25T20:17:11.610Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:17 dmz-cache flexo[10631]: [2022-04-25T20:17:17.999Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:24 dmz-cache flexo[12197]: [2022-04-25T20:17:24.102Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:30 dmz-cache flexo[12214]: [2022-04-25T20:17:30.441Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:36 dmz-cache flexo[12226]: [2022-04-25T20:17:36.606Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:42 dmz-cache flexo[12239]: [2022-04-25T20:17:42.781Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:48 dmz-cache flexo[12301]: [2022-04-25T20:17:48.787Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:17:54 dmz-cache flexo[12315]: [2022-04-25T20:17:54.762Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:00 dmz-cache flexo[14078]: [2022-04-25T20:18:00.850Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:07 dmz-cache flexo[14090]: [2022-04-25T20:18:07.153Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:13 dmz-cache flexo[14107]: [2022-04-25T20:18:13.279Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:25 dmz-cache flexo[65]: [2022-04-25T20:18:25.555Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:31 dmz-cache flexo[87]: [2022-04-25T20:18:31.632Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:37 dmz-cache flexo[658]: [2022-04-25T20:18:37.600Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Apr 25 20:18:43 dmz-cache flexo[1890]: [2022-04-25T20:18:43.609Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
May 10 03:23:14 dmz-cache flexo[58]: [2022-05-10T03:23:14.246Z INFO  flexo] Primary mirror: "https://mirror.fcix.net/archlinux/"
May 15 22:40:18 dmz-cache flexo[7743]: [2022-05-15T22:40:18.056Z INFO  flexo] Primary mirror: "https://arch.hu.fo/archlinux/"
Jun 05 18:22:22 dmz-cache flexo[65]: [2022-06-05T18:22:22.993Z INFO  flexo] Primary mirror: "https://archmirror1.octyl.net/"
Jun 09 00:59:45 dmz-cache flexo[2178]: [2022-06-09T00:59:45.662Z INFO  flexo] Primary mirror: "https://mirror.fcix.net/archlinux/"

I went ahead and updated /etc/pacman.d/mirrorlist on my flexo server. I ran reflector, so if this was the case of a bad mirror, hopefully it is gone now. I'll go ahead and remove the latency results and restart flexo.

EDIT: I just realized the mirrors potentially causing a problem ( arch.hu.fo, mirror.fcix.net/, etc. ) are still present even after updating the mirrorlist and running reflector. I suppose blacklisting them from reflector is the guaranteed way of not having this issue happen ( if it is related to those mirrors ).

Another way would just be to remove these mirrors from my mirrolist file. I am curious why these specific mirrors would be causing a problem with reflector.

EDIT2: I now see that even after pruning my /etc/pacman.d/mirrorlist file and removing mirror.fcix.net, flexi still chooses this as the primary mirror? I'm not sure how that's happening.

@nroi
Copy link
Owner

nroi commented Jun 11, 2022

Thanks for the journalctl output.

I went ahead and updated /etc/pacman.d/mirrorlist on my flexo server. I ran reflector, so if this was the case of a bad mirror, hopefully it is gone now.

Keep in mind that flexo ignores /etc/pacman.d/mirrorlist, it fetches a list of mirrors from the official JSON API and then runs latency tests to select fast mirrors. So, if you want to avoid flexo choosing bad mirrors, you need to use the mirrors_blacklist option, as explained in my previous post.

@naclander
Copy link
Author

Right, I see this in the [mirrors_auto]section of the toml file now.

I'm curious why not have an option to have flexo check /etc/pacman.d/mirrorlist? Like I mentioned I already use reflector so I know those mirrors work.

@nroi
Copy link
Owner

nroi commented Jun 11, 2022

I'm curious why not have an option to have flexo check /etc/pacman.d/mirrorlist? Like I mentioned I already use reflector so I know those mirrors work.

One of flexo's goal is to minimize the time users need to invest for mirrorlist maintenance, and not everyone uses reflector. But of course, it would be possible to implement this as an additional option.

@naclander
Copy link
Author

Just wanted to update that this is still happening, even after denylisting several mirrors in flexo. Do you know if there's a more consistent way of preventing the signature error from happening?

@nroi
Copy link
Owner

nroi commented Jul 31, 2022

I'm still trying to figure out why it happens in the first place.

Can you please check if this script runs on your machine? https://gist.github.com/nroi/492ccf2d55400746cb8084984e04002f
It's a python script that I just wrote for this particular issue. If you get an error due to requests not being available, you need to install it through pip:

pip3 install requests

On my machine, the output is:

No mismatches were detected. Matching files: 1344

If you run this script after the signature errors happen again, you should get output like the following:

Mismatches were detected for the following files:
Filename: cowsay-3.04-2-any.pkg.tar.zst
File path: /var/cache/flexo/pkg/extra/os/x86_64/cowsay-3.04-2-any.pkg.tar.zst
Expected sha256sum: c3a5b79405c206a6e0eccbaa632e8534a6457b144dfa84eaabb29a02b8b37dbc
actual sha256sum: fe4f1fd73c81532d16c75497c8cb2702e74a8cc15d8e93b3e0eb0eda46b375d5
Expected filesize: 19990
Actual filesize: 19989
CFS filesize: 19989
Modification time: 2022-07-31 21:10:21.530959

If you get this output, please post it in this issue, so I can get a better understanding of what's going on.

The script also provides a --delete flag which you can use to just delete the broken files, this may be better than clearing the entire cache.

@naclander
Copy link
Author

naclander commented Aug 7, 2022

I'll run this the next time I'm getting errors ( usually to move forward I change the mirror, then change it back ).

Looking at the script, it looks like I'm supposed to run it on the machine hosting the flexo service? The way I have it set up is that I have multiple machines, and the flexo service is running on one machine dedicated to be the package server. It is not all running on localhost.

I'll also add that sometimes I get this errors after a pacman -Syu, but if I explicitly do pacman -S archlinux-keyring && pacman -Syu the issue sometimes goes away. I am not sure why.

@nroi
Copy link
Owner

nroi commented Aug 7, 2022

Looking at the script, it looks like I'm supposed to run it on the machine hosting the flexo service?

Correct. The script checks the files downloaded by flexo, including the files with the .cfs extension, which are only available at the server running flexo.

I'll run this the next time I'm getting errors

Thanks!

@avionix-g
Copy link

avionix-g commented Aug 12, 2022

I've run into this as well. I'm running Flexo in Docker. Any commands run on the Flexo cache were run on the exported container filesystem. My local Pacman cache was cleared with pacman -Scc before running the system update.

Pacman output:

sudo pacman -Syu
:: Synchronizing package databases...
 kde-unstable                                                          158.2 KiB   227 KiB/s 00:01 [##########################################################] 100%
 liquorix is up to date
 core                                                                  159.1 KiB   250 KiB/s 00:01 [##########################################################] 100%
 extra                                                                1709.3 KiB  1269 KiB/s 00:01 [##########################################################] 100%
 community                                                               6.7 MiB  1647 KiB/s 00:04 [##########################################################] 100%
 multilib                                                              176.0 KiB   285 KiB/s 00:01 [##########################################################] 100%
:: Starting full system upgrade...
resolving dependencies...
looking for conflicting packages...
warning: dependency cycle detected:
warning: mesa will be installed before its libglvnd dependency
warning: dependency cycle detected:
warning: lib32-mesa will be installed before its lib32-libglvnd dependency

Packages (19) aspnet-runtime-6.0.8.sdk108-1  calibre-6.3.0-1  github-cli-2.14.4-1  lib32-libglvnd-1.4.0-3  lib32-libvpx1.3-1.3.0-3  lib32-mesa-22.1.6-1
              lib32-pango-1:1.50.9-1  lib32-smpeg-0.4.5-4  libbluray-1.3.2-1  libglvnd-1.4.0-3  libnfs-5.0.2-1  libnm-1.38.4-1  mesa-22.1.6-1
              mono-msbuild-16.10.1.xamarinxplat.2021.05.26.14.00-3  networkmanager-1.38.4-1  npm-8.17.0-1  pango-1:1.50.9-1  python-tomlkit-0.11.3-1
              python-urllib3-1.26.10-1

Total Installed Size:  373.55 MiB
Net Upgrade Size:        0.72 MiB

:: Proceed with installation? [Y/n] y
(19/19) checking keys in keyring                                                                   [##########################################################] 100%
(19/19) checking package integrity                                                                 [##########################################################] 100%
error: lib32-mesa: signature from "Laurent Carlier <lordheavym@gmail.com>" is invalid
:: File /var/cache/pacman/pkg/lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst is corrupted (invalid or corrupted package (PGP signature)).
Do you want to delete it? [Y/n] n
error: failed to commit transaction (invalid or corrupted package)
Errors occurred, no packages were upgraded.

SHA256 checksums

Flexo filesystem:

fd lib32-mesa -X sha256sum | sort
5bb969fedcf9d194722345476cacd2937033a44758bd0be50d1193788cb95722  var/cache/flexo/pkg/multilib/os/x86_64/lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst.sig
8b7fa49db9de03cadb58fbb9c9055dc31c482f80a8c38884b09f72ee73d9dc23  var/cache/flexo/pkg/multilib/os/x86_64/lib32-mesa-22.1.5-1-x86_64.pkg.tar.zst.sig
c7608a37fa0758b6b2701fd41cf77d3e8d1b119721dd1851281a8b6f04e95ea0  var/cache/flexo/pkg/multilib/os/x86_64/lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst

/var/cache/pacman/pkg on my local machine:

fd lib32-mesa -X sha256sum | sort
5bb969fedcf9d194722345476cacd2937033a44758bd0be50d1193788cb95722  ./lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst.sig
c7608a37fa0758b6b2701fd41cf77d3e8d1b119721dd1851281a8b6f04e95ea0  ./lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst

flexo-verify-packages script output

python3 flexo-verify-packages --flexo-pkg-dir ./var/cache/flexo/pkg
No mismatches were detected. Matching files: 49

The correct hashes:

After disabling Flexo in my mirrorlist, clearing the pacman cache, and running pacman -Syu:

fd lib32-mesa -X sha256sum | sort
5bb969fedcf9d194722345476cacd2937033a44758bd0be50d1193788cb95722  ./lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst.sig
9c4ed10babfb14832d040a971c62305f034328b98f6c7f2738c75e677b127cef  ./lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst

@avionix-g
Copy link

Here are the differing .pkg.tar.zst files:
package_tars.zip

@nroi
Copy link
Owner

nroi commented Aug 12, 2022

Here are the differing .pkg.tar.zst files: package_tars.zip

Interesting, the corrupted file seems to include only the end of the file. The corrupted file is 6338539 bytes large, and the last 6338539 bytes of the good file are identical to the corrupted file:

$ sha256sum bad_lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst
c7608a37fa0758b6b2701fd41cf77d3e8d1b119721dd1851281a8b6f04e95ea0
$ tail -c 6338539 good_lib32-mesa-22.1.6-1-x86_64.pkg.tar.zst | sha256sum
c7608a37fa0758b6b2701fd41cf77d3e8d1b119721dd1851281a8b6f04e95ea0

The same thing seems to have happened when naclander had this issue:

tail -c 134014308 linux-lts-5.15.45-1-x86_64.pkg.tar.zst | sha256sum
1af8f502f87da3c76a3cb5e25f15a90c7ecacb42b535842889aee85077f1dbb7

1af8f502f87da3c76a3cb5e25f15a90c7ecacb42b535842889aee85077f1dbb7 is the shasum posted by naclander in this thread, which shows that only the last 134014308 bytes were downloaded.

This might be caused by a bug related to how flexo handles HTTP range requests, but so far, I wasn't able to reproduce it. I'm going to look into it.

Also, I've updated the flexo-verify-package script to consider all repositories (the multilib repo previously wasn't included, which is why no mismatches have been detected in your case).

Anyone who stumbles on this issue again could help me by providing the following info:

  1. Run the flexo-verify-package python script on the machine that's running flexo and paste the output of that script.
  2. The journalctl log (or output from docker logs if you use docker) from the time frame when the download has happened, e.g. journalctl --unit=flexo --since today.

Thank you both for your input to help me troubleshoot this. The most recent version (1.6.7) includes a few more log statements which might help me to isolate the issue.

@avionix-g
Copy link

This showed up again for me. I still haven't figured out how to reliably reproduce it, but it does seem to be failing with an HTTP 416. Thanks for looking into this!

flexo-verify-package output

Mismatches were detected for the following files:

Filename:               wine-7.17-1-x86_64.pkg.tar.zst
File path:              ./var/cache/flexo/pkg/multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst
Expected sha256sum:     07d43a80980cc53447ab54dcd69b62910b7c4b586d9821d3c95ae69e6016a17e
actual sha256sum:       b1526d5da749b0b01a81b99ec8fb708249b1ee9e1c2b250de0707334cf951293
Expected filesize:      61735728
Actual filesize:        69665584
CFS filesize:           61735728
Modification time:      2022-09-10 18:01:47

Note: the modification time here is correct. I dumped the logs a while back and forgot about them until now...

docker logs output

[2022-09-10T22:01:07.633Z INFO  flexo] Received request for path "kde-unstable/os/x86_64/kde-unstable.db". Range start: 0
[2022-09-10T22:01:07.633Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2022-09-10T22:01:07.633Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2022-09-10T22:01:07.634Z INFO  flexo] Received request for path "community/os/x86_64/community.db". Range start: 0
[2022-09-10T22:01:08.083Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 160268
[2022-09-10T22:01:08.092Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 1789135
[2022-09-10T22:01:08.107Z INFO  flexo] Content length of path "community/os/x86_64/community.db" is 7257893
[2022-09-10T22:01:08.108Z INFO  flexo] Content length of path "kde-unstable/os/x86_64/kde-unstable.db" is 21326
[2022-09-10T22:01:08.156Z INFO  flexo] Received request for path "multilib/os/x86_64/multilib.db". Range start: 0
[2022-09-10T22:01:08.180Z INFO  flexo] Request served [CACHE MISS]: "kde-unstable/os/x86_64/kde-unstable.db"
[2022-09-10T22:01:08.182Z INFO  flexo] Received request for path "kde-unstable/os/x86_64/kde-unstable.db.sig". Range start: 0
[2022-09-10T22:01:08.268Z INFO  flexo] kde-unstable/os/x86_64/kde-unstable.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2022-09-10T22:01:08.268Z INFO  flexo] kde-unstable/os/x86_64/kde-unstable.db.sig was unavailable at all remote mirrors.
[2022-09-10T22:01:08.268Z INFO  flexo] Request served [NO PAYLOAD]: "kde-unstable/os/x86_64/kde-unstable.db.sig"
[2022-09-10T22:01:08.340Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2022-09-10T22:01:08.341Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2022-09-10T22:01:08.444Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2022-09-10T22:01:08.445Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2022-09-10T22:01:08.445Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2022-09-10T22:01:08.483Z INFO  flexo] Content length of path "multilib/os/x86_64/multilib.db" is 180441
[2022-09-10T22:01:08.949Z INFO  flexo] Request served [CACHE MISS]: "multilib/os/x86_64/multilib.db"
[2022-09-10T22:01:08.957Z INFO  flexo] Received request for path "multilib/os/x86_64/multilib.db.sig". Range start: 0
[2022-09-10T22:01:09.132Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2022-09-10T22:01:09.134Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2022-09-10T22:01:09.172Z INFO  flexo] multilib/os/x86_64/multilib.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2022-09-10T22:01:09.172Z INFO  flexo] multilib/os/x86_64/multilib.db.sig was unavailable at all remote mirrors.
[2022-09-10T22:01:09.172Z INFO  flexo] Request served [NO PAYLOAD]: "multilib/os/x86_64/multilib.db.sig"
[2022-09-10T22:01:09.292Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2022-09-10T22:01:09.292Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2022-09-10T22:01:09.292Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2022-09-10T22:01:10.036Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/community.db"
[2022-09-10T22:01:10.039Z INFO  flexo] Received request for path "community/os/x86_64/community.db.sig". Range start: 0
[2022-09-10T22:01:10.108Z INFO  flexo] community/os/x86_64/community.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2022-09-10T22:01:10.108Z INFO  flexo] community/os/x86_64/community.db.sig was unavailable at all remote mirrors.
[2022-09-10T22:01:10.108Z INFO  flexo] Request served [NO PAYLOAD]: "community/os/x86_64/community.db.sig"
[2022-09-10T22:01:11.336Z INFO  flexo] Received request for path "community/os/x86_64/blender-17:3.3.0-2-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:11.336Z INFO  flexo] Received request for path "community/os/x86_64/erlang-nox-25.0.4-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:11.336Z INFO  flexo] Received request for path "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:11.337Z INFO  flexo] Received request for path "community/os/x86_64/docker-1:20.10.18-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:11.337Z INFO  flexo] Received request for path "community/os/x86_64/go-2:1.19.1-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:11.652Z INFO  flexo] Content length of path "community/os/x86_64/blender-17:3.3.0-2-x86_64.pkg.tar.zst" is 73103523
[2022-09-10T22:01:11.669Z INFO  flexo] Content length of path "community/os/x86_64/go-2:1.19.1-1-x86_64.pkg.tar.zst" is 80458359
[2022-09-10T22:01:11.670Z INFO  flexo] Content length of path "community/os/x86_64/erlang-nox-25.0.4-1-x86_64.pkg.tar.zst" is 41575331
[2022-09-10T22:01:11.693Z INFO  flexo] Content length of path "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst" is 61735728
[2022-09-10T22:01:11.693Z INFO  flexo] Content length of path "community/os/x86_64/docker-1:20.10.18-1-x86_64.pkg.tar.zst" is 28908403
[2022-09-10T22:01:38.084Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/docker-1:20.10.18-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:38.085Z INFO  flexo] Received request for path "community/os/x86_64/docker-1:20.10.18-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:38.181Z INFO  flexo] Content length of path "community/os/x86_64/docker-1:20.10.18-1-x86_64.pkg.tar.zst.sig" is 590
[2022-09-10T22:01:38.182Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/docker-1:20.10.18-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:38.198Z INFO  flexo] Received request for path "community/os/x86_64/nushell-0.68.1-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:38.344Z INFO  flexo] Content length of path "community/os/x86_64/nushell-0.68.1-1-x86_64.pkg.tar.zst" is 12066760
[2022-09-10T22:01:47.210Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/nushell-0.68.1-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:47.211Z INFO  flexo] Received request for path "community/os/x86_64/nushell-0.68.1-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:47.284Z INFO  flexo] Content length of path "community/os/x86_64/nushell-0.68.1-1-x86_64.pkg.tar.zst.sig" is 566
[2022-09-10T22:01:47.285Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/nushell-0.68.1-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:47.293Z INFO  flexo] Received request for path "extra/os/x86_64/python-numpy-1.23.3-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:47.328Z INFO  flexo] Request served [CACHE MISS]: "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:47.351Z INFO  flexo] Received request for path "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:47.358Z INFO  flexo] Content length of path "extra/os/x86_64/python-numpy-1.23.3-1-x86_64.pkg.tar.zst" is 5948879
[2022-09-10T22:01:47.401Z INFO  flexo] Error: JobTerminated { channel: DownloadChannel { handle: Easy { handle: 0x7f00b801bc30, handler: DownloadState { job_state: JobState { order: DownloadOrder { requested_path: StrPath { path_buf: "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst.sig", inner: "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst.sig" }, cacheability: Cacheable }, job_resources: Some(DownloadJobResources { file_state: FileState { buf_writer: BufWriter { writer: File { fd: 10, path: "/var/cache/flexo/pkg/multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst.sig", read: false, write: true }, buffer: 0/8192 }, size_written: 0 }, header_state: HeaderState { received_header: [72, 84, 84, 80, 47, 49, 46, 49, 32, 52, 49, 54, 32, 82, 101, 113, 117, 101, 115, 116, 101, 100, 32, 82, 97, 110, 103, 101, 32, 78, 111, 116, 32, 83, 97, 116, 105, 115, 102, 105, 97, 98, 108, 101, 13, 10, 83, 101, 114, 118, 101, 114, 58, 32, 110, 103, 105, 110, 120, 13, 10, 68, 97, 116, 101, 58, 32, 83, 97, 116, 44, 32, 49, 48, 32, 83, 101, 112, 32, 50, 48, 50, 50, 32, 50, 50, 58, 48, 49, 58, 52, 55, 32, 71, 77, 84, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 58, 32, 116, 101, 120, 116, 47, 104, 116, 109, 108, 59, 32, 99, 104, 97, 114, 115, 101, 116, 61, 117, 116, 102, 45, 56, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 76, 101, 110, 103, 116, 104, 58, 32, 49, 57, 48, 13, 10, 67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 107, 101, 101, 112, 45, 97, 108, 105, 118, 101, 13, 10, 69, 120, 112, 105, 114, 101, 115, 58, 32, 83, 117, 110, 44, 32, 49, 49, 32, 83, 101, 112, 32, 50, 48, 50, 50, 32, 50, 50, 58, 48, 49, 58, 52, 55, 32, 71, 77, 84, 13, 10, 67, 97, 99, 104, 101, 45, 67, 111, 110, 116, 114, 111, 108, 58, 32, 109, 97, 120, 45, 97, 103, 101, 61, 56, 54, 52, 48, 48, 13, 10, 88, 45, 70, 114, 97, 109, 101, 45, 79, 112, 116, 105, 111, 110, 115, 58, 32, 68, 69, 78, 89, 13, 10, 88, 45, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 45, 79, 112, 116, 105, 111, 110, 115, 58, 32, 110, 111, 115, 110, 105, 102, 102, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 82, 97, 110, 103, 101, 58, 32, 98, 121, 116, 101, 115, 32, 42, 47, 53, 54, 54, 13, 10, 88, 45, 70, 114, 97, 109, 101, 45, 79, 112, 116, 105, 111, 110, 115, 58, 32, 68, 69, 78, 89, 13, 10, 88, 45, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 45, 79, 112, 116, 105, 111, 110, 115, 58, 32, 110, 111, 115, 110, 105, 102, 102, 13, 10, 13, 10], header_success: Some(Unavailable) }, last_chance: false }), tx: Sender { .. } }, properties: MirrorConfig { cache_directory: "/var/cache/flexo/pkg", mirrorlist_fallback_file: "/var/cache/flexo/state/mirrorlist", mirrorlist_latency_test_results_file: Some("/var/cache/flexo/state/latency_test_results.json"), refresh_latency_tests_after: None, port: 7878, listen_ip_address: Some("0.0.0.0"), mirror_selection_method: Auto, mirrors_predefined: [], custom_repo: None, low_speed_limit: Some(128000), low_speed_limit_formatted: None, low_speed_time_secs: Some(3), connect_timeout: None, max_speed_limit: None, num_versions_retain: Some(3), mirrors_auto: Some(MirrorsAutoConfig { mirrors_status_json_endpoint: "https://archlinux.org/mirrors/status/json/", mirrors_status_json_endpoint_fallbacks: [], mirrors_blacklist: [], https_required: true, ipv4: true, ipv6: false, max_score: 2.5, num_mirrors: 8, mirrors_random_or_sort: Sort, timeout: 350, allowed_countries: [] }) } } } }, error: HttpFailureStatus(416) }, try again
[2022-09-10T22:01:47.402Z INFO  flexo] Request served [CACHE HIT]: "multilib/os/x86_64/wine-7.17-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:47.402Z INFO  flexo] Received request for path "extra/os/x86_64/python-virtualenv-20.13.2-1-any.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:47.724Z INFO  flexo] Content length of path "extra/os/x86_64/python-virtualenv-20.13.2-1-any.pkg.tar.zst" is 5468709
[2022-09-10T22:01:48.430Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/erlang-nox-25.0.4-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:48.432Z INFO  flexo] Received request for path "community/os/x86_64/erlang-nox-25.0.4-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:48.598Z INFO  flexo] Content length of path "community/os/x86_64/erlang-nox-25.0.4-1-x86_64.pkg.tar.zst.sig" is 566
[2022-09-10T22:01:48.599Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/erlang-nox-25.0.4-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:48.600Z INFO  flexo] Received request for path "community/os/x86_64/zellij-0.31.4-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:48.745Z INFO  flexo] Content length of path "community/os/x86_64/zellij-0.31.4-1-x86_64.pkg.tar.zst" is 4180267
[2022-09-10T22:01:49.103Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/python-virtualenv-20.13.2-1-any.pkg.tar.zst"
[2022-09-10T22:01:49.104Z INFO  flexo] Received request for path "extra/os/x86_64/python-virtualenv-20.13.2-1-any.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:49.177Z INFO  flexo] Content length of path "extra/os/x86_64/python-virtualenv-20.13.2-1-any.pkg.tar.zst.sig" is 566
[2022-09-10T22:01:49.178Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/python-virtualenv-20.13.2-1-any.pkg.tar.zst.sig"
[2022-09-10T22:01:49.184Z INFO  flexo] Received request for path "core/os/x86_64/gawk-5.2.0-3-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:49.261Z INFO  flexo] Content length of path "core/os/x86_64/gawk-5.2.0-3-x86_64.pkg.tar.zst" is 1272255
[2022-09-10T22:01:49.402Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/gawk-5.2.0-3-x86_64.pkg.tar.zst"
[2022-09-10T22:01:49.410Z INFO  flexo] Received request for path "core/os/x86_64/gawk-5.2.0-3-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:49.515Z INFO  flexo] Content length of path "core/os/x86_64/gawk-5.2.0-3-x86_64.pkg.tar.zst.sig" is 141
[2022-09-10T22:01:49.516Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/gawk-5.2.0-3-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:49.517Z INFO  flexo] Received request for path "community/os/x86_64/python-prompt_toolkit-3.0.31-1-any.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:49.633Z INFO  flexo] Content length of path "community/os/x86_64/python-prompt_toolkit-3.0.31-1-any.pkg.tar.zst" is 572140
[2022-09-10T22:01:49.673Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/python-prompt_toolkit-3.0.31-1-any.pkg.tar.zst"
[2022-09-10T22:01:49.675Z INFO  flexo] Received request for path "community/os/x86_64/python-prompt_toolkit-3.0.31-1-any.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:49.703Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/python-numpy-1.23.3-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:49.703Z INFO  flexo] Received request for path "extra/os/x86_64/python-numpy-1.23.3-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:49.765Z INFO  flexo] Content length of path "community/os/x86_64/python-prompt_toolkit-3.0.31-1-any.pkg.tar.zst.sig" is 590
[2022-09-10T22:01:49.766Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/python-prompt_toolkit-3.0.31-1-any.pkg.tar.zst.sig"
[2022-09-10T22:01:49.804Z INFO  flexo] Received request for path "extra/os/x86_64/rsync-3.2.6-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:49.929Z INFO  flexo] Content length of path "extra/os/x86_64/rsync-3.2.6-1-x86_64.pkg.tar.zst" is 337369
[2022-09-10T22:01:50.006Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/rsync-3.2.6-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:50.007Z INFO  flexo] Received request for path "extra/os/x86_64/rsync-3.2.6-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:50.095Z INFO  flexo] Content length of path "extra/os/x86_64/rsync-3.2.6-1-x86_64.pkg.tar.zst.sig" is 119
[2022-09-10T22:01:50.096Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/rsync-3.2.6-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:50.097Z INFO  flexo] Received request for path "core/os/x86_64/grep-3.8-2-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:50.154Z INFO  flexo] Content length of path "extra/os/x86_64/python-numpy-1.23.3-1-x86_64.pkg.tar.zst.sig" is 566
[2022-09-10T22:01:50.155Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/python-numpy-1.23.3-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:50.172Z INFO  flexo] Received request for path "community/os/x86_64/python-docker-6.0.0-1-any.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:50.204Z INFO  flexo] Content length of path "core/os/x86_64/grep-3.8-2-x86_64.pkg.tar.zst" is 235417
[2022-09-10T22:01:50.232Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/grep-3.8-2-x86_64.pkg.tar.zst"
[2022-09-10T22:01:50.240Z INFO  flexo] Received request for path "core/os/x86_64/grep-3.8-2-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:50.263Z INFO  flexo] Content length of path "community/os/x86_64/python-docker-6.0.0-1-any.pkg.tar.zst" is 192697
[2022-09-10T22:01:50.337Z INFO  flexo] Content length of path "core/os/x86_64/grep-3.8-2-x86_64.pkg.tar.zst.sig" is 119
[2022-09-10T22:01:50.338Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/grep-3.8-2-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:50.338Z INFO  flexo] Received request for path "community/os/x86_64/lv2-1.18.10-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:50.455Z INFO  flexo] Content length of path "community/os/x86_64/lv2-1.18.10-1-x86_64.pkg.tar.zst" is 161928
[2022-09-10T22:01:50.487Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/lv2-1.18.10-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:50.514Z INFO  flexo] Received request for path "community/os/x86_64/lv2-1.18.10-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:50.604Z INFO  flexo] Content length of path "community/os/x86_64/lv2-1.18.10-1-x86_64.pkg.tar.zst.sig" is 118
[2022-09-10T22:01:50.605Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/lv2-1.18.10-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:50.607Z INFO  flexo] Received request for path "community/os/x86_64/sratom-0.6.14-1-x86_64.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:50.710Z INFO  flexo] Content length of path "community/os/x86_64/sratom-0.6.14-1-x86_64.pkg.tar.zst" is 19941
[2022-09-10T22:01:50.712Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/sratom-0.6.14-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:50.718Z INFO  flexo] Received request for path "community/os/x86_64/sratom-0.6.14-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:50.785Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/python-docker-6.0.0-1-any.pkg.tar.zst"
[2022-09-10T22:01:50.785Z INFO  flexo] Received request for path "community/os/x86_64/python-docker-6.0.0-1-any.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:50.786Z INFO  flexo] Content length of path "community/os/x86_64/sratom-0.6.14-1-x86_64.pkg.tar.zst.sig" is 119
[2022-09-10T22:01:50.786Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/sratom-0.6.14-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:01:50.819Z INFO  flexo] Received request for path "community/os/x86_64/python-certifi-2022.06.15.1-1-any.pkg.tar.zst". Range start: 0
[2022-09-10T22:01:50.886Z INFO  flexo] Content length of path "community/os/x86_64/python-docker-6.0.0-1-any.pkg.tar.zst.sig" is 590
[2022-09-10T22:01:50.886Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/python-docker-6.0.0-1-any.pkg.tar.zst.sig"
[2022-09-10T22:01:51.084Z INFO  flexo] Content length of path "community/os/x86_64/python-certifi-2022.06.15.1-1-any.pkg.tar.zst" is 8808
[2022-09-10T22:01:51.084Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/python-certifi-2022.06.15.1-1-any.pkg.tar.zst"
[2022-09-10T22:01:51.092Z INFO  flexo] Received request for path "community/os/x86_64/python-certifi-2022.06.15.1-1-any.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:51.200Z INFO  flexo] Content length of path "community/os/x86_64/python-certifi-2022.06.15.1-1-any.pkg.tar.zst.sig" is 119
[2022-09-10T22:01:51.200Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/python-certifi-2022.06.15.1-1-any.pkg.tar.zst.sig"
[2022-09-10T22:01:51.873Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/zellij-0.31.4-1-x86_64.pkg.tar.zst"
[2022-09-10T22:01:51.874Z INFO  flexo] Received request for path "community/os/x86_64/zellij-0.31.4-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:01:51.954Z INFO  flexo] Content length of path "community/os/x86_64/zellij-0.31.4-1-x86_64.pkg.tar.zst.sig" is 566
[2022-09-10T22:01:51.955Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/zellij-0.31.4-1-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:02:07.402Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/blender-17:3.3.0-2-x86_64.pkg.tar.zst"
[2022-09-10T22:02:07.404Z INFO  flexo] Received request for path "community/os/x86_64/blender-17:3.3.0-2-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:02:07.486Z INFO  flexo] Content length of path "community/os/x86_64/blender-17:3.3.0-2-x86_64.pkg.tar.zst.sig" is 566
[2022-09-10T22:02:07.487Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/blender-17:3.3.0-2-x86_64.pkg.tar.zst.sig"
[2022-09-10T22:02:09.194Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/go-2:1.19.1-1-x86_64.pkg.tar.zst"
[2022-09-10T22:02:09.196Z INFO  flexo] Received request for path "community/os/x86_64/go-2:1.19.1-1-x86_64.pkg.tar.zst.sig". Range start: 0
[2022-09-10T22:02:09.277Z INFO  flexo] Content length of path "community/os/x86_64/go-2:1.19.1-1-x86_64.pkg.tar.zst.sig" is 590
[2022-09-10T22:02:09.277Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/go-2:1.19.1-1-x86_64.pkg.tar.zst.sig"

@nroi nroi added the bug Something isn't working label Sep 25, 2022
@nroi
Copy link
Owner

nroi commented Sep 25, 2022

Thanks for the output, @avionix-g!

Could you please tell me if:

  • In general, do you have multiple clients in your LAN downloading from flexo, or just a single client?
  • If you use multiple clients, do you recall if you had multiple clients downloading simultaneously before the error occurred?

What I can tell so far from your output is this:

  • Something is wrong with the way flexo handles range requests. Flexo is supposed to make HTTP range request in the following cases:
    • If a file is already partially available. For example, if the file size is 20 MB, but 15 MB are already available, flexo is supposed to download the remaining 5 MB.
    • If the client (i.e., pacman) made a range request because the client already had the file partially available.

But in your case, Flexo seems to have made an erroneous range request. Probably something like requesting the file starting from byte x when the actual file size is less than x.

Another problem is that Flexo has stored a file of size 69665584 when the mirror reported a content length of just 61735728. Just like in the previous case where this error occurred, the locally stored file are the last 61735728 bytes of the file wine-7.17-1-x86_64.pkg.tar.zst.

nroi added a commit that referenced this issue Sep 25, 2022
@nroi
Copy link
Owner

nroi commented Oct 3, 2022

The most recent version (1.6.8) includes a few more log statements that might help troubleshoot this issue. Until I find a way to reproduce this issue, that's all I can do… Inspect the logs and hope to gain some insights.

@naclander
Copy link
Author

This issue finally happened on the host running the flexo service ( not on the clients, which more frequently get this error ). The output from the script you requested is here:

Mismatches were detected for the following files:

Filename:               calibre-6.10.0-2-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/community/os/x86_64/calibre-6.10.0-2-x86_64.pkg.tar.zst
Expected sha256sum:     1e75c0883551172a46a09062926151c571e54dfefd011e90098b96a66178006a
Actual sha256sum:       4362745c359e831f2b07b8731b682d50d082b288c2aee5f14b52b755891648ce
Expected filesize:      32971964
Actual filesize:        3357857
CFS filesize:           32971964
Modification time:      2022-12-28 04:57:06.918568
Filename:               intellij-idea-community-edition-4:2022.3.1-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/community/os/x86_64/intellij-idea-community-edition-4:2022.3.1-1-x86_64.pkg.tar.zst
Expected sha256sum:     ec0a880ad0ac936886db2aad7c71cc5114c7df5f0ee5c75c4e7c3df5c3151c7c
Actual sha256sum:       b4e4d339160489f2c3703dec15788b9b1cd0931851621a24248da2b012779277
Expected filesize:      489495978
Actual filesize:        36743082
CFS filesize:           489495978
Modification time:      2022-12-23 20:23:50.483936
Filename:               podman-4.3.1-2-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/community/os/x86_64/podman-4.3.1-2-x86_64.pkg.tar.zst
Expected sha256sum:     c19994b9d61c2ae04439f2c5e93e327c65fdf8a924f61153c304b5c58e54ea71
Actual sha256sum:       8a122531e5a70f5940e5d8320a663ad9a5832a6e900b6edefb96aa1f6aaed405
Expected filesize:      17023440
Actual filesize:        12663969
CFS filesize:           17023440
Modification time:      2022-12-24 18:30:42.578559
Filename:               pycharm-community-edition-2022.3-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/community/os/x86_64/pycharm-community-edition-2022.3-1-x86_64.pkg.tar.zst
Expected sha256sum:     32142ac375a3a856e5cf23c8a2efb0610c1bd344c6ce659c9373103e8e91bbfe
Actual sha256sum:       714c6d7e49c0aec1eb8db9c3c0ff3ebef0072f3d1ad7ec006f249748cc40f4c3
Expected filesize:      176163164
Actual filesize:        75947083
CFS filesize:           176163164
Modification time:      2022-12-23 20:24:54.791305
Filename:               rclone-1.61.1-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/community/os/x86_64/rclone-1.61.1-1-x86_64.pkg.tar.zst
Expected sha256sum:     bb3f1dac0d079d50e832ee2b2d21d6cf793bfc616f45d46c9aa5d53a7d4b8fe7
Actual sha256sum:       8d46445f54b8661d0da3749f94bec08cb839d723bd6b5e0fde7d4a9ae18cce2f
Expected filesize:      18740202
Actual filesize:        2948257
CFS filesize:           18740202
Modification time:      2022-12-28 04:57:08.498634
Filename:               signal-desktop-6.1.0-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/community/os/x86_64/signal-desktop-6.1.0-1-x86_64.pkg.tar.zst
Expected sha256sum:     5671ca259bc6a496906a30b37d4f8ac1ad9ef159cf37730410f72783ad093ff6
Actual sha256sum:       bbca46189d9daa293ddecd96343acd1b2ffa6b977f0559425f3a826c7d00848f
Expected filesize:      125133559
Actual filesize:        41371305
CFS filesize:           125133559
Modification time:      2022-12-23 20:24:12.725110
Filename:               chromium-108.0.5359.124-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/extra/os/x86_64/chromium-108.0.5359.124-1-x86_64.pkg.tar.zst
Expected sha256sum:     b9594762603801a130f4fc7f99b6ceb1293c7e2c0882d1da828d854b65ccf7dd
Actual sha256sum:       908650ce578bccb186b506908d692d75fb0dfe3845d98371fe8ae96c36bac541
Expected filesize:      91276236
Actual filesize:        63243162
CFS filesize:           91276236
Modification time:      2022-12-23 20:24:36.646362
Filename:               inkscape-1.2.2-2-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/extra/os/x86_64/inkscape-1.2.2-2-x86_64.pkg.tar.zst
Expected sha256sum:     44c7428a2b1e0c58fc94c2c8f9e828fcc15155d36b8307106ec9ea750424fbf2
Actual sha256sum:       9f5fb497a18a82f80c6a0b9f561b55c44cdce35628d0e894ae23b62226166614
Expected filesize:      23302646
Actual filesize:        9894976
CFS filesize:           23302646
Modification time:      2022-12-05 03:38:43.595129
Filename:               libcamera-0.0.3-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/extra/os/x86_64/libcamera-0.0.3-1-x86_64.pkg.tar.zst
Expected sha256sum:     2a6e91026a59a5417185574eb2cb7b653ab948937edf047e61888eb35decf894
Actual sha256sum:       632f9ac6da2b060fa96f371fe863a64e32955f0ae25a3d965b868109a721c0a4
Expected filesize:      858080
Actual filesize:        284900
CFS filesize:           284900
Modification time:      2022-12-28 04:57:08.566637
Filename:               libreoffice-fresh-7.4.3-3-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/extra/os/x86_64/libreoffice-fresh-7.4.3-3-x86_64.pkg.tar.zst
Expected sha256sum:     bf1ce46ef33e63069c8c5c7184cd7cab98eca7eb78d688a1b43082772aaa077c
Actual sha256sum:       7eb8d8cf9a043980baf1aa19ee39113d817bdf398013632f957e1725b2699260
Expected filesize:      151599525
Actual filesize:        61391248
CFS filesize:           151599525
Modification time:      2022-12-23 20:24:28.997963
Filename:               rust-1:1.66.0-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/extra/os/x86_64/rust-1:1.66.0-1-x86_64.pkg.tar.zst
Expected sha256sum:     b1f5bf01da9c56b544e583267933870a32dcc173a8d59b66af4691877a3241f3
Actual sha256sum:       2ec19e0bed90e3637e1129772f8b5159d11ed74cd309b872a1f0d7653a2ba5d0
Expected filesize:      95789121
Actual filesize:        32783518
CFS filesize:           95789121
Modification time:      2022-12-28 04:59:02.507397
Filename:               suitesparse-6.0.3-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/extra/os/x86_64/suitesparse-6.0.3-1-x86_64.pkg.tar.zst
Expected sha256sum:     95405e916c9eefde549865d870ff6a67fadfbad886eade89f7ffdfde49a98545
Actual sha256sum:       cd6888228d90703d3d5608b24f41a37d24291cbb8601139d8e02eda1a9be80d2
Expected filesize:      21856691
Actual filesize:        18005152
CFS filesize:           21856691
Modification time:      2022-12-28 04:57:24.719314
Filename:               linux-6.1.1.arch1-1-x86_64.pkg.tar.zst
File path:              /var/cache/flexo/pkg/core/os/x86_64/linux-6.1.1.arch1-1-x86_64.pkg.tar.zst
Expected sha256sum:     7fdc1e4516b059cbadaf5ad7a7c652e0d30abadc777101497b31d1f0c7de9fe4
Actual sha256sum:       64f771045107d9da97a88cb3b6b9868a5f4cefed5d88222f125fb7687bf7bee3
Expected filesize:      171887560
Actual filesize:        85910782
CFS filesize:           171887560
Modification time:      2022-12-23 20:24:37.110386
Filename:               linux-firmware-20221214.f3c283e-1-any.pkg.tar.zst
File path:              /var/cache/flexo/pkg/core/os/x86_64/linux-firmware-20221214.f3c283e-1-any.pkg.tar.zst
Expected sha256sum:     8d27a1e98cecaac0e39b4177500a8162cd83b1e26b9776cc7d42dfaaefe73539
Actual sha256sum:       6cb29815e5ede80f14db4926731061a84110cc71a75032dff6ea5db7345c24cf
Expected filesize:      173903406
Actual filesize:        85661492
CFS filesize:           173903406
Modification time:      2022-12-23 20:25:16.360420

@naclander
Copy link
Author

And some logs from the flexo service ( version 1.6.8 )

Dec 28 05:45:55 dmz-cache systemd[1]: Started central pacman cache.
Dec 28 05:45:55 dmz-cache flexo[9220]: [2022-12-28T05:45:55.585Z INFO  flexo::mirror_flexo] Retrieved 752 files with a total size of 1.64 GiB from local file system.
Dec 28 05:45:55 dmz-cache flexo[9220]: [2022-12-28T05:45:55.585Z INFO  flexo] Will switch mirror if download speed falls below 244.14 KiB/s
Dec 28 05:45:57 dmz-cache flexo[9220]: [2022-12-28T05:45:57.020Z INFO  flexo] The most recent latency test ran at 2022-12-24 15:59:39.412499903 UTC. Latency tests are scheduled to run against all mirrors after a duration of: 14days
Dec 28 05:45:57 dmz-cache flexo[9220]: [2022-12-28T05:45:57.020Z INFO  flexo] Continue to run latency test against a limited number of mirrors.
Dec 28 05:45:59 dmz-cache flexo[9220]: [2022-12-28T05:45:59.529Z INFO  flexo] Primary mirror: "https://codingflyboy.mm.fcix.net/archlinux/"
Dec 28 05:46:44 dmz-cache flexo[9220]: [2022-12-28T05:46:44.749Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
Dec 28 05:46:44 dmz-cache flexo[9220]: [2022-12-28T05:46:44.750Z INFO  flexo::mirror_flexo] File is still empty: core.db-971f7aef-4170-45cd-b06e-d2fafd6de8f0
Dec 28 05:46:44 dmz-cache flexo[9220]: [2022-12-28T05:46:44.965Z INFO  flexo::mirror_flexo] HTTP response code is 200
Dec 28 05:46:44 dmz-cache flexo[9220]: [2022-12-28T05:46:44.966Z INFO  flexo::mirror_flexo] Server replied with content length 156252 for core/os/x86_64/core.db
Dec 28 05:46:44 dmz-cache flexo[9220]: [2022-12-28T05:46:44.966Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 156252
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.079Z INFO  flexo::mirror_flexo] File size of core.db-971f7aef-4170-45cd-b06e-d2fafd6de8f0 is 156252
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.079Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.080Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.080Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-2c35f162-6181-44e4-968e-0d41b240517e
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.105Z INFO  flexo::mirror_flexo] HTTP response code is 404
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.105Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.105Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://codingflyboy.mm.fcix.net/archlinux/
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.105Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.106Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.107Z INFO  flexo::mirror_flexo] File is still empty: extra.db-f3170b16-d915-418b-9d13-a7e643de8c97
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.240Z INFO  flexo::mirror_flexo] HTTP response code is 200
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.240Z INFO  flexo::mirror_flexo] Server replied with content length 1773098 for extra/os/x86_64/extra.db
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.241Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 1773098
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.665Z INFO  flexo::mirror_flexo] File size of extra.db-f3170b16-d915-418b-9d13-a7e643de8c97 is 1773098
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.666Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.672Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.672Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-ae12dd5f-a286-460d-9cfd-db75ea25e1d8
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.697Z INFO  flexo::mirror_flexo] HTTP response code is 404
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.697Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.697Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://codingflyboy.mm.fcix.net/archlinux/
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.697Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.697Z INFO  flexo] Received request for path "community/os/x86_64/community.db". Range start: 0
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.698Z INFO  flexo::mirror_flexo] File is still empty: community.db-9a390e13-0f98-4188-a892-9b0906e09594
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.829Z INFO  flexo::mirror_flexo] HTTP response code is 200
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.830Z INFO  flexo::mirror_flexo] Server replied with content length 7516482 for community/os/x86_64/community.db
Dec 28 05:46:45 dmz-cache flexo[9220]: [2022-12-28T05:46:45.830Z INFO  flexo] Content length of path "community/os/x86_64/community.db" is 7516482
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.008Z INFO  flexo::mirror_flexo] File size of community.db-9a390e13-0f98-4188-a892-9b0906e09594 is 7516482
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.008Z INFO  flexo] Request served [CACHE MISS]: "community/os/x86_64/community.db"
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.014Z INFO  flexo] Received request for path "community/os/x86_64/community.db.sig". Range start: 0
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.016Z INFO  flexo::mirror_flexo] File is still empty: community.db.sig-0d5abdd7-e7cf-4b08-b986-94ea8a9eabdb
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.040Z INFO  flexo::mirror_flexo] HTTP response code is 404
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.040Z INFO  flexo] community/os/x86_64/community.db.sig is not available at https://codingflyboy.mm.fcix.net/archlinux/
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.040Z INFO  flexo] community/os/x86_64/community.db.sig was unavailable at all remote mirrors.
Dec 28 05:46:47 dmz-cache flexo[9220]: [2022-12-28T05:46:47.040Z INFO  flexo] Request served [NO PAYLOAD]: "community/os/x86_64/community.db.sig"
Dec 28 05:46:48 dmz-cache flexo[9220]: [2022-12-28T05:46:48.559Z INFO  flexo] Received request for path "core/os/x86_64/openssl-3.0.7-4-x86_64.pkg.tar.zst". Range start: 0
Dec 28 05:46:48 dmz-cache flexo[9220]: [2022-12-28T05:46:48.612Z INFO  flexo] Request served [CACHE HIT]: "core/os/x86_64/openssl-3.0.7-4-x86_64.pkg.tar.zst"
Dec 28 05:46:48 dmz-cache flexo[9220]: [2022-12-28T05:46:48.624Z INFO  flexo] Received request for path "core/os/x86_64/openssl-3.0.7-4-x86_64.pkg.tar.zst.sig". Range start: 0
Dec 28 05:46:48 dmz-cache flexo[9220]: [2022-12-28T05:46:48.625Z INFO  flexo] Request served [CACHE HIT]: "core/os/x86_64/openssl-3.0.7-4-x86_64.pkg.tar.zst.sig"

@nroi
Copy link
Owner

nroi commented Jan 1, 2023

Thanks for the output, @naclander

The journalctl logs you've posted don't include any of the packages where the checksum verification has failed, do you have more logs available? Try something like:

journalctl --since='2022-12-28 05:46' --until '2022-12-28 05:55' -u flexo 

@naclander
Copy link
Author

Unfortunately the next time I went to run the update the error no longer appears. I try the above command if it happens again.

@exalented
Copy link

exalented commented Sep 16, 2023

Output of flexo-verify-packages:

Mismatches were detected for the following files:

Filename:               clamav-1.2.0-1-x86_64.pkg.tar.zst
File path:              cache//extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst
Expected sha256sum:     ab3f745b8937bd65a60282b44dd345bc7ab0b9e174260b794b2424a7ee95a255
Actual sha256sum:       e0540346ecb1c5d672b3b905e9d50ccd14e96d401cb21a5e7f427812c8ad63c1
Expected filesize:      9242571
Actual filesize:        5802192
CFS filesize:           5802192
Modification time:      2023-09-07 11:45:23.681475
Filename:               spandsp-0.0.6-5-x86_64.pkg.tar.zst
File path:              cache//extra/os/x86_64/spandsp-0.0.6-5-x86_64.pkg.tar.zst
Expected sha256sum:     e4f186a6f4939d2e7c905cb6412a57cc8b0a5357d309bf1c925a34f405fb0972
Actual sha256sum:       81de9f7a675160d14a4f7f563fdfa6dad7d8954f2ee1e85f7fb9348f592bb9b1
Expected filesize:      434514
Actual filesize:        294654
CFS filesize:           434514
Modification time:      2023-05-30 20:05:50.979348
Filename:               unibilium-2.1.1-1-x86_64.pkg.tar.zst
File path:              cache//extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst
Expected sha256sum:     8604578ed6c0997313e09a82162d3b9404830c2ef6f5abeec4a677867d963132
Actual sha256sum:       787616d38ac425d3be68c4e5c2034b2cda6f9fa517339dfed1032c69881d23bd
Expected filesize:      114506
Actual filesize:        49266
CFS filesize:           49266
Modification time:      2023-09-15 13:19:23.427133
Filename:               wine-mono-8.0.0-1-any.pkg.tar.zst
File path:              cache//extra/os/x86_64/wine-mono-8.0.0-1-any.pkg.tar.zst
Expected sha256sum:     b01137b5035593c9c9c03d2937e99dd547ee3227046bc124792eed7b1c155fd7
Actual sha256sum:       bbfa943fc71febb5449120e708b9cfd7492649c4e98aa6470d8d183174610cde
Expected filesize:      45856969
Actual filesize:        442106
CFS filesize:           45856969
Modification time:      2023-05-30 20:03:23.090158

some flexo docker logs:
clamav

pacman_cache  | [2023-09-07T18:45:15.020Z INFO  flexo] Received request for path "extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst". Range start: 0
pacman_cache  | [2023-09-07T18:45:15.020Z INFO  flexo::mirror_flexo] File is still empty: clamav-1.2.0-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-07T18:45:15.355Z INFO  flexo::mirror_flexo] HTTP response code is 200
pacman_cache  | [2023-09-07T18:45:15.355Z INFO  flexo::mirror_flexo] Server replied with content length 566 for extra/os/x86_64/ffmpeg-2:6.0-9-x86_64.pkg.tar.zst.sig
pacman_cache  | [2023-09-07T18:45:15.355Z INFO  flexo::mirror_flexo] Created CFS file: "/var/cache/flexo/pkg/extra/os/x86_64/ffmpeg-2:6.0-9-x86_64.pkg.tar.zst.sig" has size 566
pacman_cache  | [2023-09-07T18:45:15.355Z INFO  flexo::mirror_flexo] File size of ffmpeg-2:6.0-9-x86_64.pkg.tar.zst.sig is 566
pacman_cache  | [2023-09-07T18:45:15.578Z INFO  flexo::mirror_flexo] HTTP response code is 206
pacman_cache  | [2023-09-07T18:45:15.578Z INFO  flexo::mirror_flexo] Server replied with content length 5802192 for extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-07T18:45:15.578Z INFO  flexo::mirror_flexo] Created CFS file: "/var/cache/flexo/pkg/extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst" has size 5802192
pacman_cache  | [2023-09-07T18:45:15.578Z INFO  flexo] Content length of path "extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst" is 5802192
pacman_cache  | [2023-09-07T18:45:23.683Z INFO  flexo::mirror_flexo] File size of clamav-1.2.0-1-x86_64.pkg.tar.zst is 5802192
pacman_cache  | [2023-09-07T18:45:23.684Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst"
pacman_cache  | [2023-09-07T18:45:23.780Z INFO  flexo] Received request for path "extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst.sig". Range start: 0
pacman_cache  | [2023-09-07T18:45:23.781Z INFO  flexo::mirror_flexo] File is still empty: clamav-1.2.0-1-x86_64.pkg.tar.zst.sig
pacman_cache  | [2023-09-07T18:45:23.866Z INFO  flexo::mirror_flexo] HTTP response code is 200
pacman_cache  | [2023-09-07T18:45:23.866Z INFO  flexo::mirror_flexo] Server replied with content length 566 for extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst.sig
pacman_cache  | [2023-09-07T18:45:23.866Z INFO  flexo::mirror_flexo] Created CFS file: "/var/cache/flexo/pkg/extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst.sig" has size 566
pacman_cache  | [2023-09-07T18:45:23.866Z INFO  flexo::mirror_flexo] File size of clamav-1.2.0-1-x86_64.pkg.tar.zst.sig is 566
pacman_cache  | [2023-09-07T18:45:23.866Z INFO  flexo] Content length of path "extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst.sig" is 566
pacman_cache  | [2023-09-07T18:45:23.866Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/clamav-1.2.0-1-x86_64.pkg.tar.zst.sig"

unibilium

pacman_cache  | [2023-09-15T20:19:20.465Z INFO  flexo] Received request for path "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst". Range start: 0
pacman_cache  | [2023-09-15T20:19:20.465Z INFO  flexo::mirror_flexo] File is still empty: neovim-0.9.2-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-15T20:19:20.465Z INFO  flexo::mirror_flexo] File is still empty: unibilium-2.1.1-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-15T20:19:20.565Z INFO  flexo::mirror_flexo] HTTP response code is 200
pacman_cache  | [2023-09-15T20:19:20.565Z INFO  flexo::mirror_flexo] Server replied with content length 6405046 for extra/os/x86_64/neovim-0.9.2-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-15T20:19:20.565Z INFO  flexo::mirror_flexo] Created CFS file: "/var/cache/flexo/pkg/extra/os/x86_64/neovim-0.9.2-1-x86_64.pkg.tar.zst" has size 6405046
pacman_cache  | [2023-09-15T20:19:20.565Z INFO  flexo] Content length of path "extra/os/x86_64/neovim-0.9.2-1-x86_64.pkg.tar.zst" is 6405046
pacman_cache  | [2023-09-15T20:19:21.383Z INFO  flexo::mirror_flexo] HTTP response code is 206
pacman_cache  | [2023-09-15T20:19:21.383Z INFO  flexo::mirror_flexo] Server replied with content length 49266 for extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-15T20:19:21.383Z INFO  flexo::mirror_flexo] Created CFS file: "/var/cache/flexo/pkg/extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst" has size 49266
pacman_cache  | [2023-09-15T20:19:21.383Z INFO  flexo] Content length of path "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst" is 49266
pacman_cache  | [2023-09-15T20:19:23.429Z INFO  flexo::mirror_flexo] File size of unibilium-2.1.1-1-x86_64.pkg.tar.zst is 49266
pacman_cache  | [2023-09-15T20:19:23.430Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst"
pacman_cache  | [2023-09-15T20:19:23.535Z INFO  flexo] Received request for path "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig". Range start: 0
pacman_cache  | [2023-09-15T20:19:23.536Z INFO  flexo::mirror_flexo] File is still empty: unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig
pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo::mirror_flexo] HTTP response code is 416
pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo] Error: JobTerminated { channel: DownloadChannel { handle: Easy { handle: 0x7fb510018e70, handler: DownloadState { job_state: JobState { order: DownloadOrder { requested_path: StrPath { path_buf: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig", inner: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig" }, cacheability: Cacheable }, job_resources: Some(DownloadJobResources { file_state: FileState { buf_writer: BufWriter { writer: File { fd: 9, path: "/var/cache/flexo/pkg/extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig", read: false, write: true }, buffer: 0/8192 }, size_written: 0, filename: "unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig" }, header_state: HeaderState { received_header: [72, 84, 84, 80, 47, 49, 46, 49, 32, 52, 49, 54, 32, 82, 101, 113, 117, 101, 115, 116, 101, 100, 32, 82, 97, 110, 103, 101, 32, 78, 111, 116, 32, 83, 97, 116, 105, 115, 102, 105, 97, 98, 108, 101, 13, 10, 83, 101, 114, 118, 101, 114, 58, 32, 110, 103, 105, 110, 120, 13, 10, 68, 97, 116, 101, 58, 32, 70, 114, 105, 44, 32, 49, 53, 32, 83, 101, 112, 32, 50, 48, 50, 51, 32, 50, 48, 58, 49, 57, 58, 50, 51, 32, 71, 77, 84, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 58, 32, 116, 101, 120, 116, 47, 104, 116, 109, 108, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 76, 101, 110, 103, 116, 104, 58, 32, 49, 57, 48, 13, 10, 67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 107, 101, 101, 112, 45, 97, 108, 105, 118, 101, 13, 10, 75, 101, 101, 112, 45, 65, 108, 105, 118, 101, 58, 32, 116, 105, 109, 101, 111, 117, 116, 61, 53, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 82, 97, 110, 103, 101, 58, 32, 98, 121, 116, 101, 115, 32, 42, 47, 53, 54, 54, 13, 10, 13, 10], header_success: Some(Unavailable) }, last_chance: false }), tx: Sender { .. } }, properties: MirrorConfig { cache_directory: "/var/cache/flexo/pkg", mirrorlist_fallback_file: "/var/cache/flexo/state/mirrorlist", mirrorlist_latency_test_results_file: Some("/var/cache/flexo/state/latency_test_results.json"), refresh_latency_tests_after: None, port: 7878, listen_ip_address: Some("0.0.0.0"), mirror_selection_method: Auto, mirrors_predefined: [], custom_repo: None, low_speed_limit: Some(128000), low_speed_limit_formatted: None, low_speed_time_secs: Some(3), connect_timeout: None, max_speed_limit: None, num_versions_retain: Some(3), mirrors_auto: Some(MirrorsAutoConfig { mirrors_status_json_endpoint: "https://archlinux.org/mirrors/status/json/", mirrors_status_json_endpoint_fallbacks: [], mirrors_blacklist: [], https_required: true, ipv4: true, ipv6: false, max_score: 2.5, num_mirrors: 8, mirrors_random_or_sort: Sort, timeout: 350, allowed_countries: [] }) } } } }, error: HttpFailureStatus(416) }, try again
pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo] Request served [CACHE HIT]: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig"
pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo::mirror_flexo] File is still empty: unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig
pacman_cache  | [2023-09-15T20:19:23.604Z INFO  flexo] Received request for path "extra/os/x86_64/libluv-1.45.0_0-1-x86_64.pkg.tar.zst". Range start: 0
pacman_cache  | [2023-09-15T20:19:23.604Z INFO  flexo::mirror_flexo] File is still empty: libluv-1.45.0_0-1-x86_64.pkg.tar.zst
pacman_cache  | [2023-09-15T20:19:24.488Z INFO  flexo::mirror_flexo] HTTP response code is 200
pacman_cache  | [2023-09-15T20:19:24.488Z INFO  flexo::mirror_flexo] Server replied with content length 566 for extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig
pacman_cache  | [2023-09-15T20:19:24.488Z INFO  flexo::mirror_flexo] Created CFS file: "/var/cache/flexo/pkg/extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig" has size 566
pacman_cache  | [2023-09-15T20:19:24.488Z INFO  flexo::mirror_flexo] File size of unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig is 566

HTTP response code is 206. AKA the remote isn't ready with the file yet.
Which sometimes results in 416.
When flexo receives a 206 or 416 response you could recheck the remote header (a configurable amount of times) until the response is 200.

@nroi
Copy link
Owner

nroi commented Sep 23, 2023

Thanks for providing the logs, @exalented!

HTTP response code is 206. AKA the remote isn't ready with the file yet.

actually, 206 is the expected response when the client requests just part of the file. For example, when pacman initiates a download from flexo, then aborts it, and later on downloads the same file again, the expected behavior is that flexo resumes the download, so it sends a range request to the remote mirror and the remote mirror responds with 206.
416 is the response when the client for some reason sends a wrong range request that cannot be fulfilled by the server.

I wasn't able to completely figure out what exactly is happening for what reasons from the logs, but something that definitely looks wrong is this:

pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo] Error: JobTerminated { channel: DownloadChannel { handle: Easy { handle: 0x7fb510018e70, handler: DownloadState { job_state: JobState { order: DownloadOrder { requested_path: StrPath { path_buf: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig", inner: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig" }, cacheability: Cacheable }, job_resources: Some(DownloadJobResources { file_state: FileState { buf_writer: BufWriter { writer: File { fd: 9, path: "/var/cache/flexo/pkg/extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig", read: false, write: true }, buffer: 0/8192 }, size_written: 0, filename: "unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig" }, header_state: HeaderState { received_header: [72, 84, 84, 80, 47, 49, 46, 49, 32, 52, 49, 54, 32, 82, 101, 113, 117, 101, 115, 116, 101, 100, 32, 82, 97, 110, 103, 101, 32, 78, 111, 116, 32, 83, 97, 116, 105, 115, 102, 105, 97, 98, 108, 101, 13, 10, 83, 101, 114, 118, 101, 114, 58, 32, 110, 103, 105, 110, 120, 13, 10, 68, 97, 116, 101, 58, 32, 70, 114, 105, 44, 32, 49, 53, 32, 83, 101, 112, 32, 50, 48, 50, 51, 32, 50, 48, 58, 49, 57, 58, 50, 51, 32, 71, 77, 84, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 58, 32, 116, 101, 120, 116, 47, 104, 116, 109, 108, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 76, 101, 110, 103, 116, 104, 58, 32, 49, 57, 48, 13, 10, 67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 107, 101, 101, 112, 45, 97, 108, 105, 118, 101, 13, 10, 75, 101, 101, 112, 45, 65, 108, 105, 118, 101, 58, 32, 116, 105, 109, 101, 111, 117, 116, 61, 53, 13, 10, 67, 111, 110, 116, 101, 110, 116, 45, 82, 97, 110, 103, 101, 58, 32, 98, 121, 116, 101, 115, 32, 42, 47, 53, 54, 54, 13, 10, 13, 10], header_success: Some(Unavailable) }, last_chance: false }), tx: Sender { .. } }, properties: MirrorConfig { cache_directory: "/var/cache/flexo/pkg", mirrorlist_fallback_file: "/var/cache/flexo/state/mirrorlist", mirrorlist_latency_test_results_file: Some("/var/cache/flexo/state/latency_test_results.json"), refresh_latency_tests_after: None, port: 7878, listen_ip_address: Some("0.0.0.0"), mirror_selection_method: Auto, mirrors_predefined: [], custom_repo: None, low_speed_limit: Some(128000), low_speed_limit_formatted: None, low_speed_time_secs: Some(3), connect_timeout: None, max_speed_limit: None, num_versions_retain: Some(3), mirrors_auto: Some(MirrorsAutoConfig { mirrors_status_json_endpoint: "https://archlinux.org/mirrors/status/json/", mirrors_status_json_endpoint_fallbacks: [], mirrors_blacklist: [], https_required: true, ipv4: true, ipv6: false, max_score: 2.5, num_mirrors: 8, mirrors_random_or_sort: Sort, timeout: 350, allowed_countries: [] }) } } } }, error: HttpFailureStatus(416) }, try again
pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo] Request served [CACHE HIT]: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig"

The header we have received (1st line in the logs) is this one:

HTTP/1.1 416 Requested Range Not Satisfiable
Server: nginx
Date: Fri, 15 Sep 2023 20:19:23 GMT
Content-Type: text/html
Content-Length: 190
Connection: keep-alive
Keep-Alive: timeout=5
Content-Range: bytes */566

Notice it actually says "try again" in the log, so the re-try logic is already in place. And yet, in almost the exact same time, we have this in the logs:

pacman_cache  | [2023-09-15T20:19:23.596Z INFO  flexo] Request served [CACHE HIT]: "extra/os/x86_64/unibilium-2.1.1-1-x86_64.pkg.tar.zst.sig"

So, even though we haven't received the required payload from the server, we just serve whatever trash to the client (probably an empty file or an HTML file saying "Not found"), and only after we served this trash to the client, flexo fetches the actual content from the remote mirror.

This does not explain everything, but it's a start.

Thanks again for providing the logs, I will look into it.

@ulrichSchreiner
Copy link

hi,

any progress with this bug? it happens to me about once a week. about a year ago i never had this problem. perhaps because i now have 5 computers using nexo as a central mirror.

@nroi
Copy link
Owner

nroi commented Jul 2, 2024

any progress with this bug?

Unfortunately, no. I'd like to devote more time to this project, but I don't have much time to spare at the moment, and this is the kind of problem that really requires more than just a bit of focussed time. The fact that this issue has never happened for me makes it difficult.

I hope I find more time in the near future. But if anyone notices a pattern, or even better, a way to reproduce this issue, let me know.

@nroi
Copy link
Owner

nroi commented Aug 4, 2024

Is there anyone impacted by this bug who is not using flexo via docker? This info could be useful for me when trying to reproduce this issue.

@naclander
Copy link
Author

I was not using flexo via docker when I noticed this bug. I haven't been running into this bug in a while, the only main difference I can recall between what changed is that the bandwidth of the server running flexo increased. I don't know how/if slow download speeds and invalid signatures are related, but that's the only difference I can recall.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

5 participants