search

anatol / pacoloco

Caching proxy server for Arch Linux pacman
MIT License
199 stars 30 forks source link

DB requests failing: `superfluous response.WriteHeader call` #69

Closed Vernoxvernax closed 1 year ago

Vernoxvernax commented 1 year ago

Pacoloco has been running just fine for quite a few months now, but I recently discovered the opposite. Here is what I've found:

Feb 28 03:01:10 Server pacoloco[2956722]: pacoloco.go:446: downloading http://mirror.lty.me/archlinux/core/os/x86_64/core.db
Feb 28 03:01:10 Server pacoloco[2956722]: pacoloco.go:456: write tcp 192.168.178.2:9129->192.168.178.3:41712: write: broken pipe
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:446: downloading http://mirrors.kernel.org/archlinux/core/os/x86_64/core.db
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:456: write tcp 192.168.178.2:9129->192.168.178.3:41712: write: broken pipe
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/core.db: no such file or directory
Feb 28 03:01:11 Server pacoloco[2956722]: server.go:3197: http: superfluous response.WriteHeader call from main.pacolocoHandler (pacoloco.go:139)
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/core.db.sig: no such file or directory
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:446: downloading http://mirror.lty.me/archlinux/extra/os/x86_64/extra.db
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:456: write tcp 192.168.178.2:9129->192.168.178.3:41724: write: broken pipe
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:446: downloading http://mirrors.kernel.org/archlinux/extra/os/x86_64/extra.db
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:456: write tcp 192.168.178.2:9129->192.168.178.3:41724: write: broken pipe
Feb 28 03:01:11 Server pacoloco[2956722]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/extra.db: no such file or directory
Feb 28 03:01:11 Server pacoloco[2956722]: server.go:3197: http: superfluous response.WriteHeader call from main.pacolocoHandler (pacoloco.go:139)
Feb 28 03:01:12 Server pacoloco[2956722]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/extra.db.sig: no such file or directory
Feb 28 03:01:12 Server pacoloco[2956722]: pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/community.db
Feb 28 03:01:13 Server pacoloco[2956722]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/community.db.sig: no such file or directory
Feb 28 03:01:13 Server pacoloco[2956722]: pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/multilib.db
Feb 28 03:01:13 Server pacoloco[2956722]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/multilib.db.sig: no such file or directory

Downloading extra.db with wget works just fine, so I suppose no network related issues. Config is almost identical to the pre-generated one (not using a http-proxy).

pacoloco 1.2-2
Kernel: 6.1.12-arch1-1
Vernoxvernax commented 1 year ago

It get's even weirder. Prefetching jobs seem to run just fine (assume the error logging is the same):

Feb 28 04:00:00 Server pacoloco[789]: prefetch.go:255: Starting prefetching routine...
Feb 28 04:00:00 Server pacoloco[789]: prefetch.go:182: Cleaning the db...
Feb 28 04:00:00 Server pacoloco[789]: prefetch.go:217: Db cleaned.
Feb 28 04:00:00 Server pacoloco[789]: prefetch.go:261: Starting prefetching packages...
Feb 28 04:00:00 Server pacoloco[789]: pacoloco.go:376: downloading http://mirror.lty.me/archlinux/extra/os/x86_64/extra.db
Feb 28 04:00:02 Server pacoloco[789]: repo_db_mirror.go:125: Extracting /var/cache/pacoloco/tmp-db/extra.db...
Feb 28 04:00:02 Server pacoloco[789]: repo_db_mirror.go:134: Parsing /var/cache/pacoloco/tmp-db/extra.db.tar...
Feb 28 04:00:02 Server pacoloco[789]: repo_db_mirror.go:136: Parsed /var/cache/pacoloco/tmp-db/extra.db.tar.
Feb 28 04:00:02 Server pacoloco[789]: repo_db_mirror.go:143: Adding entries to db...
Feb 28 04:00:02 Server pacoloco[789]: repo_db_mirror.go:179: Added entries to db.
Feb 28 04:00:02 Server pacoloco[789]: pacoloco.go:376: downloading http://mirror.lty.me/archlinux/community/os/x86_64/community.db
Feb 28 04:00:04 Server pacoloco[789]: repo_db_mirror.go:125: Extracting /var/cache/pacoloco/tmp-db/community.db...
Feb 28 04:00:04 Server pacoloco[789]: repo_db_mirror.go:134: Parsing /var/cache/pacoloco/tmp-db/community.db.tar...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:136: Parsed /var/cache/pacoloco/tmp-db/community.db.tar.
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:143: Adding entries to db...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:179: Added entries to db.
Feb 28 04:00:05 Server pacoloco[789]: pacoloco.go:376: downloading http://mirror.lty.me/archlinux/multilib/os/x86_64/multilib.db
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:125: Extracting /var/cache/pacoloco/tmp-db/multilib.db...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:134: Parsing /var/cache/pacoloco/tmp-db/multilib.db.tar...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:136: Parsed /var/cache/pacoloco/tmp-db/multilib.db.tar.
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:143: Adding entries to db...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:179: Added entries to db.
Feb 28 04:00:05 Server pacoloco[789]: pacoloco.go:376: downloading http://mirror.lty.me/archlinux/core/os/x86_64/core.db
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:125: Extracting /var/cache/pacoloco/tmp-db/core.db...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:134: Parsing /var/cache/pacoloco/tmp-db/core.db.tar...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:136: Parsed /var/cache/pacoloco/tmp-db/core.db.tar.
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:143: Adding entries to db...
Feb 28 04:00:05 Server pacoloco[789]: repo_db_mirror.go:179: Added entries to db.
Feb 28 04:00:05 Server pacoloco[789]: prefetch.go:263: Finished prefetching packages!
Feb 28 04:00:05 Server pacoloco[789]: prefetch.go:264: Finished prefetching routine!
Feb 28 04:00:05 Server pacoloco[789]: prefetch.go:45: On 2023-02-28 04:59:59.999999973 +0100 CET m=+4871.187376883 the prefetching routine will be run again
Focshole commented 1 year ago

http: superfluous response.WriteHeader call from main.pacolocoHandler (pacoloco.go:139)

That is not an issue, I mean, it usually isn't. It is a fallback mechanism (set the header to 404 if i recall correctly), which is superfluous in this case. I agree that it can be avoided, it is not clean

write tcp 192.168.178.2:9129->192.168.178.3:41724: write: broken pipe This is the issue. Why did the pipe broke? Is there something breaking your connection? It happened to me once that my router decided to drop all local network connections for no reason, I rebooted it and it went fine and never happened again. No clue so far on what could have caused it

Vernoxvernax commented 1 year ago

@Focshole I must admit, the router which I got from my ISP is not the most reliable. All of the machines (server, client, router) have been rebooted at least once while this is happening. I have no idea how pacoloco really works, but I doubt the connection to the server is why its failing. Running pacman -Syyu, successfully transfers all of the databases (the outdated ones).

Client:

 core                                                                                               153.4 KiB   415 KiB/s 00:00 [##############################################################################] 100%
 extra                                                                                             1739.8 KiB  4.28 MiB/s 00:00 [##############################################################################] 100%
 community                                                                                            7.2 MiB  16.6 MiB/s 00:00 [##############################################################################] 100%
 multilib                                                                                           165.9 KiB   436 KiB/s 00:00 [##############################################################################] 100%
 archlinuxfr                                                                                          7.5 KiB   102 KiB/s 00:00 [##############################################################################] 100%
 llvm-svn                                                                                             9.0 KiB  50.2 KiB/s 00:00 [##############################################################################] 100%
 mesa-git                                                                                             8.1 KiB  67.5 KiB/s 00:00 [##############################################################################] 100%

Server:

Feb 28 15:09:31 Server pacoloco[789]: pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/core.db
Feb 28 15:09:32 Server pacoloco[789]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/core.db.sig: no such file or directory
Feb 28 15:09:32 Server pacoloco[789]: pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/extra.db
Feb 28 15:09:33 Server pacoloco[789]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/extra.db.sig: no such file or directory
Feb 28 15:09:33 Server pacoloco[789]: pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/community.db
Feb 28 15:09:34 Server pacoloco[789]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/community.db.sig: no such file or directory
Feb 28 15:09:34 Server pacoloco[789]: pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/multilib.db
Feb 28 15:09:34 Server pacoloco[789]: pacoloco.go:138: open /var/cache/pacoloco/pkgs/archlinux/multilib.db.sig: no such file or directory

Thats what I think at least.

Focshole commented 1 year ago

What do you see on a client what the failure happens? Does it download all files without issues?

pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/extra.db

BTW, this is not good, dbs should not be cached. I suspect it happened due to a bug in the prefetching implementation that does not delete the db package. Try a rm /var/cache/pacoloco/pkgs/archlinux/*.db and let me know if it temporarily fixes it!

Vernoxvernax commented 1 year ago

What do you see on a client what the failure happens? Does it download all files without issues?

pacoloco.go:486: serving cached file /var/cache/pacoloco/pkgs/archlinux/extra.db

BTW, this is not good, dbs should not be cached. I suspect it happened due to a bug in the prefetching implementation that does not delete the db package. Try a rm /var/cache/pacoloco/pkgs/archlinux/*.db and let me know if it temporarily fixes it!

When running pacman with -Syyu all of the old database files were transfered without any issues.

Anyways. I deleted all of the .db files in the cache and now it seems to be working again. 138 new updates, YAY!

Thank you very much for the fix :)

Focshole commented 1 year ago

Perfect, the issue is not actually solved, I'd reopen the issue so that a proper fix will be implemented!