search

nroi / flexo

a central pacman cache
MIT License
172 stars 10 forks source link

Panic when no content-length header received #75

Closed Zebradil closed 2 years ago

Zebradil commented 2 years ago

Flexo panics when I try to upgrade system on one of my machines.

I have three machines: "Mirror" (M) which runs flexo (and also uses it as a mirror) and two "clients" (A and B) which uses M as their mirror.

When I'm running pacman -Suy on one of the machines I'm getting errors.

Looking at logs in journal reveals that flexo panics on unwrap here. If I understood correctly, this happens because a remote mirror's response doesn't contain content-length header. Unfortunately, I was not able to see which exact remote mirror it is.

Logs ``` Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.178Z DEBUG flexo] Established connection with client. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.178Z DEBUG flexo] All set, spawning new thread. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.178Z DEBUG flexo] Established connection with client. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] All set, spawning new thread. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Started new thread. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Reading header from client. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo::mirror_flexo] Received header from client Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Schedule new job Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Established connection with client. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] All set, spawning new thread. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Started new thread. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Reading header from client. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Job was scheduled, will serve from growing file Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo::mirror_flexo] Received header from client Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Started new thread. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Reading header from client. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Schedule new job Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo::mirror_flexo] Received header from client Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Attempt number 1 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Schedule new job Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo::provider_guards] Selected DownloadProvider { uri: "https://archmirror.it/repos/", name: "https://archmirror.it/repos/", mirror_results: MirrorResults { total_time: 0ns, namelookup_duration: 0ns, connect_duration: 0ns, pretransfer_time: 0ns, starttransfer_time: 0ns }, country_code: "Unknown" }, number of usages: 1 [ThreadId(5)] Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Selected provider: ProviderGuard { guarded_provider: DownloadProvider { uri: "https://archmirror.it/repos/", name: "https://archmirror.it/repos/", mirror_results: MirrorResults { total_time: 0ns, namelookup_duration: 0ns, connect_duration: 0ns, pretransfer_time: 0ns, starttransfer_time: 0ns }, country_code: "Unknown" } } Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Trying to serve core/os/x86_64/core.db via https://archmirror.it/repos/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] No providers are left after this provider? false Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Job was scheduled, will serve from growing file Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Attempt to establish new connection Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.179Z DEBUG flexo] Establish a new connection to https://archmirror.it/repos/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Job was scheduled, will serve from growing file Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Attempt to create file: "/tmp/flexo/uncacheable/core/os/x86_64/core.db-6357ff0a-9e28-4275-964b-f9cfb058b651" Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Attempt number 1 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Attempt number 1 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::provider_guards] Selected DownloadProvider { uri: "https://mirror.osbeck.com/archlinux/", name: "https://mirror.osbeck.com/archlinux/", mirror_results: MirrorResults { total_time: 0ns, namelookup_duration: 0ns, connect_duration: 0ns, pretransfer_time: 0ns, starttransfer_time: 0ns }, country_code: "Unknown" }, number of usages: 1 [ThreadId(7)] Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Selected provider: ProviderGuard { guarded_provider: DownloadProvider { uri: "https://mirror.osbeck.com/archlinux/", name: "https://mirror.osbeck.com/archlinux/", mirror_results: MirrorResults { total_time: 0ns, namelookup_duration: 0ns, connect_duration: 0ns, pretransfer_time: 0ns, starttransfer_time: 0ns }, country_code: "Unknown" } } Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Fetch package from remote mirror: https://archmirror.it/repos/core/os/x86_64/core.db. Resume from byte 0. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] No speed limit was set. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Trying to serve community/os/x86_64/community.db via https://mirror.osbeck.com/archlinux/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::provider_guards] Selected DownloadProvider { uri: "https://ftp.halifax.rwth-aachen.de/archlinux/", name: "https://ftp.halifax.rwth-aachen.de/archlinux/", mirror_results: MirrorResults { total_time: 0ns, namelookup_duration: 0ns, connect_duration: 0ns, pretransfer_time: 0ns, starttransfer_time: 0ns }, country_code: "Unknown" }, number of usages: 1 [ThreadId(6)] Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] No providers are left after this provider? false Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Start download from https://archmirror.it/repos/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Selected provider: ProviderGuard { guarded_provider: DownloadProvider { uri: "https://ftp.halifax.rwth-aachen.de/archlinux/", name: "https://ftp.halifax.rwth-aachen.de/archlinux/", mirror_results: MirrorResults { total_time: 0ns, namelookup_duration: 0ns, connect_duration: 0ns, pretransfer_time: 0ns, starttransfer_time: 0ns }, country_code: "Unknown" } } Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Attempt to establish new connection Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Trying to serve extra/os/x86_64/extra.db via https://ftp.halifax.rwth-aachen.de/archlinux/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] No providers are left after this provider? false Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Establish a new connection to https://mirror.osbeck.com/archlinux/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Attempt to establish new connection Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Attempt to create file: "/tmp/flexo/uncacheable/community/os/x86_64/community.db-c9916ddb-29f5-42aa-b192-4431e10e3302" Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Fetch package from remote mirror: https://mirror.osbeck.com/archlinux/community/os/x86_64/community.db. Resume from byte 0. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo] Establish a new connection to https://ftp.halifax.rwth-aachen.de/archlinux/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] No speed limit was set. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Start download from https://mirror.osbeck.com/archlinux/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.180Z DEBUG flexo::mirror_flexo] Attempt to create file: "/tmp/flexo/uncacheable/extra/os/x86_64/extra.db-995e92a5-43cf-448c-bd17-76574e2eef9a" Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.181Z DEBUG flexo::mirror_flexo] Fetch package from remote mirror: https://ftp.halifax.rwth-aachen.de/archlinux/extra/os/x86_64/extra.db. Resume from byte 0. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.181Z DEBUG flexo::mirror_flexo] No speed limit was set. Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.181Z DEBUG flexo::mirror_flexo] Start download from https://ftp.halifax.rwth-aachen.de/archlinux/ Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.312Z DEBUG flexo::mirror_flexo] Received complete header from remote mirror Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.312Z DEBUG flexo::mirror_flexo] HTTP response code is 200 Sep 28 20:11:36 home flexo[507945]: thread '' panicked at 'called `Option::unwrap()` on a `None` value', src/mirror_flexo.rs:789[2021-09-28T20:11:36.312Z DEBUG flexo::mirror_flexo] Received complete header from remote mirror Sep 28 20:11:36 home flexo[507945]: :23 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.312Z DEBUG flexo::mirror_flexo] HTTP response code is 200 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.312Z DEBUG flexo::mirror_flexo] Content length is 140497 Sep 28 20:11:36 home flexo[507945]: stack backtrace: Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.312Z DEBUG flexo::mirror_flexo] Sending content length: 140497 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.313Z DEBUG flexo::mirror_flexo] Begin to transfer body to file core/os/x86_64/core.db Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.313Z DEBUG flexo] Received content length via channel: 140497 Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.313Z DEBUG flexo] Sending header to client: "HTTP/1.1 200 OK\r\nServer: flexo\r\nDate: Tue, 28 Sep 2021 20:11:36 GMT\r\nFlexo-Payload-Origin: RemoteMirror\r\nContent-Length: 140497\r\n\r\n" Sep 28 20:11:36 home flexo[507945]: [2021-09-28T20:11:36.313Z DEBUG flexo] Header was sent to the client. Sep 28 20:11:36 home flexo[507945]: 0: 0xaaaac93aadb4 - Sep 28 20:11:36 home flexo[507945]: 1: 0xaaaac93cb1a0 - Sep 28 20:11:36 home flexo[507945]: 2: 0xaaaac93a5f04 - Sep 28 20:11:36 home flexo[507945]: 3: 0xaaaac93acf70 - Sep 28 20:11:36 home flexo[507945]: 4: 0xaaaac93aca88 - Sep 28 20:11:36 home flexo[507945]: 5: 0xaaaac92ef3dc - Sep 28 20:11:36 home flexo[507945]: 6: 0xaaaac93ad600 - Sep 28 20:11:36 home flexo[507945]: 7: 0xaaaac93ad0d4 - Sep 28 20:11:36 home flexo[507945]: 8: 0xaaaac93ab250 - Sep 28 20:11:36 home flexo[507945]: 9: 0xaaaac93ad068 - Sep 28 20:11:36 home flexo[507945]: 10: 0xaaaac92a1dc8 - Sep 28 20:11:36 home flexo[507945]: 11: 0xaaaac92a1d4c - Sep 28 20:11:36 home flexo[507945]: 12: 0xaaaac92c8e60 - Sep 28 20:11:36 home flexo[507945]: 13: 0xaaaac92dffe8 - Sep 28 20:11:36 home flexo[507945]: 14: 0xaaaac9309a44 - Sep 28 20:11:36 home flexo[507945]: 15: 0xffffa7b3f6a4 - Sep 28 20:11:36 home flexo[507945]: 16: 0xffffa7b230bc - Sep 28 20:11:36 home flexo[507945]: 17: 0xffffa7b4fb94 - Sep 28 20:11:36 home flexo[507945]: 18: 0xffffa7b36fec - Sep 28 20:11:36 home flexo[507945]: 19: 0xffffa7b3866c - curl_multi_perform Sep 28 20:11:36 home flexo[507945]: 20: 0xffffa7b0fc10 - curl_easy_perform Sep 28 20:11:36 home flexo[507945]: 21: 0xaaaac92c501c - Sep 28 20:11:36 home flexo[507945]: 22: 0xaaaac92fc72c - Sep 28 20:11:36 home flexo[507945]: 23: 0xaaaac92fe670 - Sep 28 20:11:36 home flexo[507945]: 24: 0xaaaac93b2870 - Sep 28 20:11:36 home flexo[507945]: 25: 0xffffa7aa1f44 - start_thread Sep 28 20:11:36 home flexo[507945]: 26: 0xffffa793995c - thread_start Sep 28 20:11:36 home flexo[507945]: 27: 0x0 - Sep 28 20:11:36 home systemd[1]: flexo.service: Main process exited, code=exited, status=1/FAILURE Sep 28 20:11:36 home systemd[1]: flexo.service: Failed with result 'exit-code'. ```

Any ideas how to debug this further?

UPD: I'm using a predefined list of mirrors and regenerating the list resolves the issue. But I'm still puzzled: why this error was reproducible only on one machine...

nroi commented 2 years ago

Thanks again for reporting this!

Any ideas how to debug this further?

I have all I need to know, since you have mentioned:

Looking at logs in journal reveals that flexo panics on unwrap here.

Flexo is supposed to work well even if individual mirrors behave strangely, so the correct behavior would be to try the next mirror if that mirror does not respond with the content length. Just assuming the content length is set and panicking when it's not is incomplete error handling which leads to Flexo not being as robust as it's supposed to be.