GNU bug report logs -
#38411
HTTP pipelining of narinfo requests broken for https://ci.guix.gnu.org
Previous Next
Reported by: Ludovic Courtès <ludo <at> gnu.org>
Date: Thu, 28 Nov 2019 09:23:01 UTC
Severity: serious
Done: Gábor Boskovits <boskovits <at> gmail.com>
Bug is archived. No further changes may be made.
To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 38411 in the body.
You can then email your comments to 38411 AT debbugs.gnu.org in the normal way.
Toggle the display of automated, internal messages from the tracker.
Report forwarded
to
bug-guix <at> gnu.org
:
bug#38411
; Package
guix
.
(Thu, 28 Nov 2019 09:23:01 GMT)
Full text and
rfc822 format available.
Acknowledgement sent
to
Ludovic Courtès <ludo <at> gnu.org>
:
New bug report received and forwarded. Copy sent to
bug-guix <at> gnu.org
.
(Thu, 28 Nov 2019 09:23:02 GMT)
Full text and
rfc822 format available.
Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
[Message part 1 (text/plain, inline)]
Starting from a couple of days ago (it seems; roughly around the same
time berlin hit ENOSPC), people have been experiencing issues during the
“updating list of substitutes” phase from https://ci.guix.gnu.org, where
they’d get an ugly backtrace when they’re at 80% or so.
Here’s a small reproducer:
[http-pipelining.scm (text/plain, inline)]
(use-modules (guix scripts substitute)
(srfi srfi-1)
(srfi srfi-26)
(web uri)
(web request)
(web response)
(rnrs io ports))
(define http-multiple-get
(@@ (guix scripts substitute) http-multiple-get))
(define %base-url
"https://berlin.guix.gnu.org")
(define %request-count
;; Number of requests to send. Starts failing at 85 (that is, we don't
;; receive the 85th response).
200)
(http-multiple-get (string->uri %base-url)
(lambda (request response port result)
(let ((len (or (response-content-length response)
0)))
(pk 'resp (length result)
(uri-path (request-uri request)))
(get-bytevector-n port len)
(cons result result)))
'()
(unfold (cut >= <> %request-count)
(lambda (n)
(build-request
(string->uri
(string-append
%base-url
"/"
(string-pad (number->string n) 32 #\a)
".narinfo"))
#:method 'GET
#:headers '((User-Agent . "GNU Guile"))))
1+
0)
#:verify-certificate? #f)
[Message part 3 (text/plain, inline)]
You’ll see that it hangs waiting for a response as soon as you pipeline
85 requests or more.
Note that:
1. https://bayfront.guix.gnu.org doesn’t have that problem;
2. http://ci.guix.gnu.org doesn’t have that problem;
3. when you send 85 requests, it hangs waiting for the 85th response;
but when you send 200 requests, it hangs waiting for the 160th
response; so it seems it’s not just a matter of TLS record size.
I suspected something having to do with TLS record size limits, but item
#3 above may invalidate that hypothesis.
The weird thing is that we haven’t change the config of berlin in recent
days. Berlin runs nginx 1.17.5 on openssl 1.1.1d, while bayfront runs
nginx 1.17.0 on openssl 1.0.2p.
I very much welcome any ideas you may have!
Thanks,
Ludo’.
Severity set to 'serious' from 'normal'
Request was from
Ludovic Courtès <ludo <at> gnu.org>
to
control <at> debbugs.gnu.org
.
(Thu, 28 Nov 2019 09:25:01 GMT)
Full text and
rfc822 format available.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#38411
; Package
guix
.
(Thu, 28 Nov 2019 10:00:02 GMT)
Full text and
rfc822 format available.
Message #10 received at 38411 <at> debbugs.gnu.org (full text, mbox):
> The weird thing is that we haven’t change the config of berlin in recent
> days. Berlin runs nginx 1.17.5 on openssl 1.1.1d, while bayfront runs
> nginx 1.17.0 on openssl 1.0.2p.
A new data point: nginx 1.17.4 from a month ago works fine:
--8<---------------cut here---------------start------------->8---
root <at> berlin ~/maintenance/hydra# guix system list-generations 2m
[…]
Generation 238 Oct 23 2019 18:02:22
file name: /var/guix/profiles/system-238-link
canonical file name: /gnu/store/28xk8ny9qslyqgi7pjyz4d2x0xrxpw07-system
label: GNU with Linux-Libre 5.3.7
bootloader: grub
root device: label: "my-root"
kernel: /gnu/store/qpasq1pkzb47w5pjzs80pvslv1n7ja1m-linux-libre-5.3.7/bzImage
[…]
root <at> berlin ~/maintenance/hydra# guix gc -R /gnu/store/28xk8ny9qslyqgi7pjyz4d2x0xrxpw07-system|grep nginx
/gnu/store/4gbpgcr4zc4qf59yq2a008maycfwra4n-shepherd-nginx.scm
/gnu/store/3gqi5cahcwjfvv0bbfqv8ifir2vrqirh-nginx.conf
/gnu/store/s9fm4d5ii8bnh9zv5k78mzjvcl3dipbh-shepherd-nginx.go
/gnu/store/zj3mxk3r2dka56favm357kmgywnv5imk-nginx-1.17.4
root <at> berlin ~/maintenance/hydra# guix gc --references /gnu/store/zj3mxk3r2dka56favm357kmgywnv5imk-nginx-1.17.4/sbin/nginx |grep ssl
/gnu/store/1dvkm6b97667qd36rsnw4g6isnsmpym7-openssl-1.1.1d
--8<---------------cut here---------------end--------------->8---
So for now berlin is running this nginx. I’ll try with 1.17.6 and
1.17.4 on top of current master.
Ludo’.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#38411
; Package
guix
.
(Thu, 28 Nov 2019 10:05:02 GMT)
Full text and
rfc822 format available.
Message #13 received at 38411 <at> debbugs.gnu.org (full text, mbox):
Ludovic Courtès <ludo <at> gnu.org> skribis:
> You’ll see that it hangs waiting for a response as soon as you pipeline
> 85 requests or more.
When you look at /var/log/guix-publish.log, you see that nginx did not
forward the 85th request (and beyond) to ‘guix publish’.
Interestingly, if you C-c the client while it’s waiting for further
responses, nginx suddenly forwards all the pending requests to ‘guix
publish’.
Ludo’.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#38411
; Package
guix
.
(Thu, 28 Nov 2019 10:19:01 GMT)
Full text and
rfc822 format available.
Message #16 received at 38411 <at> debbugs.gnu.org (full text, mbox):
nginx 1.17.6 is similarly broken:
--8<---------------cut here---------------start------------->8---
root <at> berlin ~/maintenance/hydra# guix describe
Generation 45 Nov 28 2019 11:02:51 (current)
guix 18a5575
repository URL: https://git.savannah.gnu.org/git/guix.git
branch: master
commit: 18a5575ec530f0e7a2e27f2aa3b5addf20da0f87
root <at> berlin ~/maintenance/hydra# guix build nginx
/gnu/store/6q44kjf59rgkvn0ip8m0454ybszhjpy0-nginx-1.17.6
root <at> berlin ~/maintenance/hydra# guix gc --references $(guix build nginx)|grep ssl
/gnu/store/1dvkm6b97667qd36rsnw4g6isnsmpym7-openssl-1.1.1d
--8<---------------cut here---------------end--------------->8---
Ludo'.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#38411
; Package
guix
.
(Thu, 28 Nov 2019 10:30:02 GMT)
Full text and
rfc822 format available.
Message #19 received at 38411 <at> debbugs.gnu.org (full text, mbox):
AFAICS everything is working fine with this config:
--8<---------------cut here---------------start------------->8---
root <at> berlin ~/maintenance/hydra# guix describe
Generation 45 Nov 28 2019 11:02:51 (current)
guix 18a5575
repository URL: https://git.savannah.gnu.org/git/guix.git
branch: master
commit: 18a5575ec530f0e7a2e27f2aa3b5addf20da0f87
root <at> berlin ~/maintenance/hydra# git log |head
commit 9fdb990982006a4d0ddb68aa71351cc76ef50cdc
Author: Ludovic Courtès <ludo <at> gnu.org>
Date: Thu Nov 28 11:23:29 2019 +0100
nginx: berlin: Use nginx 1.17.4.
* hydra/nginx/berlin.scm (nginx-1.17.4): New variable.
(%nginx-configuration)[nginx]: New field.
--8<---------------cut here---------------end--------------->8---
Please let me know if you encounter any issues!
I’ll leave it at that for now, but we’ll have to pay attention to that
in future upgrades. (Ideally we’d report a bug to nginx but that’s
tricky enough that this alone would take much more time than I can
allocate to it.)
Ludo’.
Reply sent
to
Gábor Boskovits <boskovits <at> gmail.com>
:
You have taken responsibility.
(Wed, 25 Dec 2019 16:52:02 GMT)
Full text and
rfc822 format available.
Notification sent
to
Ludovic Courtès <ludo <at> gnu.org>
:
bug acknowledged by developer.
(Wed, 25 Dec 2019 16:52:02 GMT)
Full text and
rfc822 format available.
Message #24 received at 38411-done <at> debbugs.gnu.org (full text, mbox):
This was an upstream regression introduced in nginx 1.17.5.
It is fixed in 1.17.7. Fixed by updating nginx to 1.17.7 in commit:
32dfde905229e593f9fe60795d2490f99c27aad5
and updating berlin config in maintenance on commit:
87d451e9c3381b21e6c7208372576abed84df1e6.
This is mentioned on then nginx 1.17.7 release notes as:
Bugfix: a timeout might occur while handling pipelined requests in an
SSL connection; the bug had appeared in 1.17.5.
g_bor
--
OpenPGP Key Fingerprint: 7988:3B9F:7D6A:4DBF:3719:0367:2506:A96C:CF63:0B21
Information forwarded
to
bug-guix <at> gnu.org
:
bug#38411
; Package
guix
.
(Thu, 26 Dec 2019 18:15:01 GMT)
Full text and
rfc822 format available.
Message #27 received at 38411 <at> debbugs.gnu.org (full text, mbox):
Hi Gábor,
help-debbugs <at> gnu.org (GNU bug Tracking System) skribis:
> This was an upstream regression introduced in nginx 1.17.5.
> It is fixed in 1.17.7. Fixed by updating nginx to 1.17.7 in commit:
> 32dfde905229e593f9fe60795d2490f99c27aad5
> and updating berlin config in maintenance on commit:
> 87d451e9c3381b21e6c7208372576abed84df1e6.
>
> This is mentioned on then nginx 1.17.7 release notes as:
>
> Bugfix: a timeout might occur while handling pipelined requests in an
> SSL connection; the bug had appeared in 1.17.5.
I’m really happy you were able to pinpoint the issue and to help
upstream diagnose it. The power of free software!
Thank you,
Ludo’.
bug archived.
Request was from
Debbugs Internal Request <help-debbugs <at> gnu.org>
to
internal_control <at> debbugs.gnu.org
.
(Fri, 24 Jan 2020 12:24:04 GMT)
Full text and
rfc822 format available.
This bug report was last modified 4 years and 93 days ago.
Previous Next
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.