Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
On Fri, Aug 06, 2021 at 05:08:40PM +0900, Mike Hommey wrote: > Package: snapshot.debian.org > Followup-For: Bug #960304 > > Dear Maintainer, > > We're hitting this problem regularly on Mozilla CI (from using dget), > and what is probably a variant of this bug with apt, which fails with, > for example: > > [task 2021-08-05T21:27:09.094Z] Err:187 > http://snapshot.debian.org/archive/debian/20210208T213147Z jessie/main amd64 > adwaita-icon-theme all 3.14.0-2 > [task 2021-08-05T21:27:09.094Z] Undetermined Error [IP: 193.62.202.27 80] > (...) > [task 2021-08-05T21:27:23.590Z] Err:202 > http://snapshot.debian.org/archive/debian/20210208T213147Z jessie/main amd64 > libicu52 amd64 52.1-8+deb8u7 > [task 2021-08-05T21:27:23.591Z] Undetermined Error [IP: 193.62.202.27 80] > (...) > [task 2021-08-05T21:28:41.210Z] E: Failed to fetch > http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/a/adwaita-icon-theme/adwaita-icon-theme_3.14.0-2_all.deb > Undetermined Error [IP: 193.62.202.27 80] > [task 2021-08-05T21:28:41.210Z] E: Failed to fetch > http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/i/icu/libicu52_52.1-8+deb8u7_amd64.deb > Undetermined Error [IP: 193.62.202.27 80] > > Corresponding server-side log for the same url: > 54.162.202.139 - - [05/Aug/2021:21:27:08 +] "GET > http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/a/adwaita-icon-theme/adwaita-icon-theme_3.14.0-2_all.deb > HTTP/1.1" 200 3518464 "-" "Debian APT-HTTP/1.3 (1.8.2.2)" > 54.202.218.195 - - [05/Aug/2021:21:39:12 +] "GET > http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/a/adwaita-icon-theme/adwaita-icon-theme_3.14.0-2_all.deb > HTTP/1.1" 200 9978092 "-" "Debian APT-HTTP/1.3 (1.8.2.2)" > Hi, it looks like yesterday's config change wasn't enough, and we still hit "LRU reached nuke_limit" / "Could not get storage" errors in varnish (except now only with files that are smaller than 10MB, since we no longer cache larger ones). Will need to figure out the right tradeoffs. Thanks, Julien
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
Package: snapshot.debian.org Followup-For: Bug #960304 Dear Maintainer, We're hitting this problem regularly on Mozilla CI (from using dget), and what is probably a variant of this bug with apt, which fails with, for example: [task 2021-08-05T21:27:09.094Z] Err:187 http://snapshot.debian.org/archive/debian/20210208T213147Z jessie/main amd64 adwaita-icon-theme all 3.14.0-2 [task 2021-08-05T21:27:09.094Z] Undetermined Error [IP: 193.62.202.27 80] (...) [task 2021-08-05T21:27:23.590Z] Err:202 http://snapshot.debian.org/archive/debian/20210208T213147Z jessie/main amd64 libicu52 amd64 52.1-8+deb8u7 [task 2021-08-05T21:27:23.591Z] Undetermined Error [IP: 193.62.202.27 80] (...) [task 2021-08-05T21:28:41.210Z] E: Failed to fetch http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/a/adwaita-icon-theme/adwaita-icon-theme_3.14.0-2_all.deb Undetermined Error [IP: 193.62.202.27 80] [task 2021-08-05T21:28:41.210Z] E: Failed to fetch http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/i/icu/libicu52_52.1-8+deb8u7_amd64.deb Undetermined Error [IP: 193.62.202.27 80] Corresponding server-side log for the same url: 54.162.202.139 - - [05/Aug/2021:21:27:08 +] "GET http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/a/adwaita-icon-theme/adwaita-icon-theme_3.14.0-2_all.deb HTTP/1.1" 200 3518464 "-" "Debian APT-HTTP/1.3 (1.8.2.2)" 54.202.218.195 - - [05/Aug/2021:21:39:12 +] "GET http://snapshot.debian.org/archive/debian/20210208T213147Z/pool/main/a/adwaita-icon-theme/adwaita-icon-theme_3.14.0-2_all.deb HTTP/1.1" 200 9978092 "-" "Debian APT-HTTP/1.3 (1.8.2.2)" Mike
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
Hi Julien, Quoting Julien Cristau (2021-08-05 13:45:15) > > Can you confirm that I still need to limit my download speed to a certain > > number of bytes per second or limit the number of files I download per hour > > below a certain threshold? > > > We cap new connections, but there's no limit on download speed as far as I > know. could the download limits, be it rate-limit or connection limit be documented somewhere? I'm maintaining a number of tools and services in Debian (debrebuild, debbisect, metasnap, debootsnap) that interface with snapshot.d.o and while I managed to figure out some settings that seem to work by trial and error, it would be great if the tools we ship in Debian could properly respect the download limits of snapshot.d.o. Thanks! cheers, josch signature.asc Description: signature
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
On Thu, Aug 05, 2021 at 12:36:02PM +0200, Johannes Schauer Marin Rodrigues wrote: > On Wed, 4 Aug 2021 10:55:09 +0200 Julien Cristau wrote: > > I just had a look at this again. It seems the issue comes from our > > varnish setup, as things are fine when hitting apache directly. But the > > combination of streaming and a mix of small and large files in varnish's > > cache leads to things like the below, where varnish gives up after > > hitting nuke_limit (50) files to make space in the cache. > > thanks a lot for looking into this! > > Maybe some problems are gone now, but when I drop the measures in my code that > implemented the heavy throttling that was necessary in the past, I now run > into > the same problems like before. So as far as my use of snapshot.d.o goes, it > doesn't seem as if anything has changed. > > Can you confirm that I still need to limit my download speed to a certain > number of bytes per second or limit the number of files I download per hour > below a certain threshold? > We cap new connections, but there's no limit on download speed as far as I know. Cheers, Julien
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
References: Hi Julien, On Wed, 4 Aug 2021 10:55:09 +0200 Julien Cristau wrote: > I just had a look at this again. It seems the issue comes from our > varnish setup, as things are fine when hitting apache directly. But the > combination of streaming and a mix of small and large files in varnish's > cache leads to things like the below, where varnish gives up after > hitting nuke_limit (50) files to make space in the cache. thanks a lot for looking into this! Maybe some problems are gone now, but when I drop the measures in my code that implemented the heavy throttling that was necessary in the past, I now run into the same problems like before. So as far as my use of snapshot.d.o goes, it doesn't seem as if anything has changed. Can you confirm that I still need to limit my download speed to a certain number of bytes per second or limit the number of files I download per hour below a certain threshold? Thanks! cheers, josch signature.asc Description: signature
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
Hi, I just had a look at this again. It seems the issue comes from our varnish setup, as things are fine when hitting apache directly. But the combination of streaming and a mix of small and large files in varnish's cache leads to things like the below, where varnish gives up after hitting nuke_limit (50) files to make space in the cache. Cheers, Julien > jcristau@sallinen:~$ sudo varnishlog -g session -q 'ReqUrl eq > "/file/51288439bde385157c889f23483b467608586aad"' > * << Session >> 3937381 > - Begin sess 0 HTTP/1 > - SessOpen 2a01:cb08:88c7:5b00:6798:1a76:ef57:4714 58440 a1 > 2001:630:206:4000:1a1a:0:c13e:ca1b 80 1628066418.824244 26 > - Link req 3937382 rxreq > - SessClose REM_CLOSE 2.846 > - End > ** << Request >> 3937382 > -- Begin req 3937381 rxreq > -- Timestamp Start: 1628066418.824321 0.00 0.00 > -- Timestamp Req: 1628066418.824321 0.00 0.00 > -- ReqStart 2a01:cb08:88c7:5b00:6798:1a76:ef57:4714 58440 a1 > -- ReqMethod GET > -- ReqURL /file/51288439bde385157c889f23483b467608586aad > -- ReqProtocolHTTP/1.1 > -- ReqHeader Host: snapshot.debian.org > -- ReqHeader User-Agent: curl/7.74.0 > -- ReqHeader Accept: */* > -- ReqHeader X-Forwarded-For: 2a01:cb08:88c7:5b00:6798:1a76:ef57:4714 > -- VCL_call RECV > -- VCL_return hash > -- VCL_call HASH > -- VCL_return lookup > -- VCL_call MISS > -- VCL_return fetch > -- Link bereq 3937383 fetch > -- Timestamp Fetch: 1628066418.826448 0.002127 0.002127 > -- RespProtocol HTTP/1.1 > -- RespStatus 200 > -- RespReason OK > -- RespHeader Date: Wed, 04 Aug 2021 08:40:18 GMT > -- RespHeader Server: Apache > -- RespHeader X-Content-Type-Options: nosniff > -- RespHeader X-Frame-Options: sameorigin > -- RespHeader Referrer-Policy: no-referrer > -- RespHeader X-Xss-Protection: 1 > -- RespHeader Permissions-Policy: interest-cohort=() > -- RespHeader Last-Modified: Fri, 20 Apr 2018 20:58:57 GMT > -- RespHeader ETag: "2c0cb0ca-56a4df4e5684a" > -- RespHeader Content-Length: 739029194 > -- RespHeader X-Clacks-Overhead: GNU Terry Pratchett > -- RespHeader Cache-Control: max-age=31536000, public > -- RespHeader X-Varnish: 3937382 > -- RespHeader Age: 0 > -- RespHeader Via: 1.1 varnish (Varnish/6.1) > -- VCL_call DELIVER > -- RespHeader connection: close > -- VCL_return deliver > -- Timestamp Process: 1628066418.826480 0.002160 0.32 > -- RespHeader Accept-Ranges: bytes > -- Timestamp Resp: 1628066421.667356 2.843036 2.840876 > -- ReqAcct128 0 128 512 19857408 19857920 > -- End > *** << BeReq>> 3937383 > --- Begin bereq 3937382 fetch > --- Timestamp Start: 1628066418.824419 0.00 0.00 > --- BereqMethodGET > --- BereqURL /file/51288439bde385157c889f23483b467608586aad > --- BereqProtocol HTTP/1.1 > --- BereqHeaderHost: snapshot.debian.org > --- BereqHeaderUser-Agent: curl/7.74.0 > --- BereqHeaderAccept: */* > --- BereqHeaderX-Forwarded-For: 2a01:cb08:88c7:5b00:6798:1a76:ef57:4714 > --- BereqHeaderAccept-Encoding: gzip > --- BereqHeaderX-Varnish: 3937383 > --- VCL_call BACKEND_FETCH > --- VCL_return fetch > --- BackendOpen32 default 127.0.0.1 80 127.0.0.1 56612 > --- BackendStart 127.0.0.1 80 > --- Timestamp Bereq: 1628066418.824718 0.000299 0.000299 > --- Timestamp Beresp: 1628066418.826314 0.001895 0.001596 > --- BerespProtocol HTTP/1.1 > --- BerespStatus 200 > --- BerespReason OK > --- BerespHeader Date: Wed, 04 Aug 2021 08:40:18 GMT > --- BerespHeader Server: Apache > --- BerespHeader X-Content-Type-Options: nosniff > --- BerespHeader X-Frame-Options: sameorigin > --- BerespHeader Referrer-Policy: no-referrer > --- BerespHeader X-Xss-Protection: 1 > --- BerespHeader Permissions-Policy: interest-cohort=() > --- BerespHeader Upgrade: h2,h2c > --- BerespHeader Connection: Upgrade > --- BerespHeader Last-Modified: Fri, 20 Apr 2018 20:58:57 GMT > --- BerespHeader ETag: "2c0cb0ca-56a4df4e5684a" > --- BerespHeader Accept-Ranges: bytes > --- BerespHeader Content-Length: 739029194 > --- BerespHeader X-Clacks-Overhead: GNU Terry Pratchett > --- BerespHeader Cache-Control: max-age=31536000, public > --- TTLRFC 31536000 10 0 1628066419 1628066419 1628066418 0 > 31536000 cacheable > --- VCL_call BACKEND_RESPONSE > --- VCL_return deliver > --- Filters > --- Storagefile s0 > --- Fetch_Body 3 length stream > --- ExpKillLRU_Cand p=0x7fa236c79b00 f=0x0 r=1 > --- ExpKillLRU x=3873725 > --- ExpKillLRU_Cand p=0x7fa236c6f700 f=0x0 r=1 > --- ExpKillLRU x=3696172 > --- ExpKillLRU_Cand p=0x7fa238320d40 f=0x0 r=1 > --- ExpKillLRU x=3873726 >
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
Severity: serious This problem is still present, and is making the snapshot service unusable for many people. At the time of writing, this is the status: $ wget https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb --2020-10-13 12:50:28-- https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Resolving snapshot.debian.org (snapshot.debian.org)... 193.62.202.27, 185.17.185.185, 2001:630:206:4000:1a1a:0:c13e:ca1b, ... Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 200 OK Length: 739029194 (705M) Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb.4’ libreoffice-dbg_4.3.3-2+deb8 3%[> ] 25,03M 11,1MB/sin 2,3s 2020-10-13 12:50:31 (11,1 MB/s) - Connection closed at byte 26247168. Retrying. --2020-10-13 12:50:32-- (try: 2) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 712782026 (680M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb.4’ libreoffice-dbg_4.3.3-2+deb8 7%[+=> ] 52,22M 10,9MB/sin 2,5s 2020-10-13 12:50:34 (10,9 MB/s) - Connection closed at byte 54755328. Retrying. --2020-10-13 12:50:36-- (try: 3) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 684273866 (653M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb.4’ libreoffice-dbg_4.3.3-2+deb8 9%[+++> ] 66,02M 9,89MB/sin 1,4s 2020-10-13 12:50:38 (9,89 MB/s) - Connection closed at byte 69222400. Retrying. --2020-10-13 12:50:41-- (try: 4) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 669806794 (639M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb.4’ libreoffice-dbg_4.3.3-2+deb8 12%[> ] 88,97M 10,5MB/sin 2,2s 2020-10-13 12:50:44 (10,5 MB/s) - Connection closed at byte 93290496. Retrying. ^C $ As you can see, the connection is forcibly closed by the server and wget has to retry repeatedly. Apt does not retry connections by default, instead it fails completely. You have to rerun the apt command again and again until all packages are successfully downloaded, which can require a large number of retries and a very long time. It is not always trivial to trigger this bug. It comes and goes with time, perhaps due to general network load. One rather reliable way of triggering it seems to be to install buster on a machine and then dist-upgrade to a recent snapshot. This results in a large number of downloads, which snapshot eventually starts to abort. Once it has started aborting downloads, the bug can be triggered by plain wget or curl calls. The source of the problem is unidentified, but one guess is that Varnish somehow erroneously interprets the rapid file accesses as a denial-of-service attack and applies restrictions. /Björn
Bug#960304: snapshot.debian.org: Snapshot repo repeatedly cutting off connection, returning partial content
Package: snapshot.debian.org Followup-For: Bug #960304 Hi, this issue persists/reappears and makes snapshot.d.o unusable via apt for any large package. Reproduced from IP addresses in , ipv4 and ipv6 connectivity. From an .hr IP: [11:09] /tmp => wget -nd https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb --2020-10-13 11:09:24-- https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Resolving snapshot.debian.org (snapshot.debian.org)... 2001:630:206:4000:1a1a:0:c13e:ca1b, 2001:1af8:4020:b030:deb::185, 185.17.185.185, ... Connecting to snapshot.debian.org (snapshot.debian.org)|2001:630:206:4000:1a1a:0:c13e:ca1b|:443... connected. HTTP request sent, awaiting response... 200 OK Length: 739029194 (705M) Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb’ libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb 3%[==> ] 27.06M 19.7MB/sin 1.4s 2020-10-13 11:09:26 (19.7 MB/s) - Connection closed at byte 28377088. Retrying. --2020-10-13 11:09:27-- (try: 2) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|2001:630:206:4000:1a1a:0:c13e:ca1b|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 710652106 (678M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb’ libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb 7%[+++===> ] 50.31M 17.4MB/sin 1.3s 2020-10-13 11:09:28 (17.4 MB/s) - Connection closed at byte 52756480. Retrying. --2020-10-13 11:09:30-- (try: 3) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|2001:630:206:4000:1a1a:0:c13e:ca1b|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 686272714 (654M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb’ libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb 9%[+++=> ] 66.34M 14.6MB/sin 1.1s 2020-10-13 11:09:31 (14.6 MB/s) - Connection closed at byte 69566464. Retrying. ^C Another try from a .de IP: y% wget -4 -nd https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb --2020-10-13 10:34:28-- https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Resolving snapshot.debian.org (snapshot.debian.org)... 193.62.202.27, 185.17.185.185 Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 200 OK Length: 739029194 (705M) Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb’ libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb 6%[=> ] 46,56M 50,4MB/s in 0,9s 2020-10-13 10:34:29 (50,4 MB/s) - Connection closed at byte 48824320. Retrying. --2020-10-13 10:34:30-- (try: 2) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 690204874 (658M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb’ libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb18%[++> ] 131,44M 46,5MB/s in 1,8s 2020-10-13 10:34:32 (46,5 MB/s) - Connection closed at byte 137822208. Retrying. --2020-10-13 10:34:34-- (try: 3) https://snapshot.debian.org/archive/debian/20200917T084540Z/pool/main/libr/libreoffice/libreoffice-dbg_4.3.3-2%2Bdeb8u11_amd64.deb Connecting to snapshot.debian.org (snapshot.debian.org)|193.62.202.27|:443... connected. HTTP request sent, awaiting response... 206 Partial Content Length: 739029194 (705M), 601206986 (573M) remaining Saving to: ‘libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb’ libreoffice-dbg_4.3.3-2+deb8u11_amd64.deb23%[+++> ] 163,00M 35,9MB/s in 0,9s 2020-10-13 10:34:35 (35,9 MB/s) - Connection closed at byte 170917888. Retrying. ^C Regards, Zoran *** Reporter,
