#47867 [1.2.1 pre-release testing] substitute downloading and TLS errors

Message #60 received at 47867@debbugs.gnu.org (full text, mbox, reply):

Received: (at 47867) by debbugs.gnu.org; 23 Apr 2021 09:19:41 +0000
From debbugs-submit-bounces@debbugs.gnu.org Fri Apr 23 05:19:41 2021
Received: from localhost ([127.0.0.1]:36188 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces@debbugs.gnu.org>)
	id 1lZryO-0000fu-Aq
	for submit@debbugs.gnu.org; Fri, 23 Apr 2021 05:19:41 -0400
Received: from eggs.gnu.org ([209.51.188.92]:58060)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <ludo@gnu.org>) id 1lZryL-0000fe-M4
 for 47867@debbugs.gnu.org; Fri, 23 Apr 2021 05:19:39 -0400
Received: from fencepost.gnu.org ([2001:470:142:3::e]:38338)
 by eggs.gnu.org with esmtp (Exim 4.90_1)
 (envelope-from <ludo@gnu.org>)
 id 1lZryF-0002TT-Nx; Fri, 23 Apr 2021 05:19:31 -0400
Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=40550 helo=ribbon)
 by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256)
 (Exim 4.82) (envelope-from <ludo@gnu.org>)
 id 1lZryE-0002ZY-96; Fri, 23 Apr 2021 05:19:31 -0400
From: Ludovic Courtès <ludo@gnu.org>
To: "pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de>
Subject: Re: bug#47867: [1.2.1 pre-release testing] substitute downloading
 and TLS errors
References: <87lf9hsh9t.fsf@gmail.com>
 <20210418093856.a6r2zqw2gks56dg5@pelzflorian.localdomain>
 <87a6pvnbjg.fsf@gnu.org>
 <20210418113337.z3afnp4lmt55cjvw@pelzflorian.localdomain>
 <20210418121006.4ihop3umb2oyofum@pelzflorian.localdomain>
 <20210419080516.piqb52s32h3fe5ag@pelzflorian.localdomain>
 <20210420012113.jcwuzfx6k3by5nvo@pelzflorian.localdomain>
 <20210420152754.a3ucylrdugrmxu57@pelzflorian.localdomain>
 <8735vk8ttp.fsf@gnu.org>
 <20210421201751.3mygidtwio2yz7j4@pelzflorian.localdomain>
Date: Fri, 23 Apr 2021 11:19:28 +0200
In-Reply-To: <20210421201751.3mygidtwio2yz7j4@pelzflorian.localdomain>
 (pelzflorian@pelzflorian.de's message of "Wed, 21 Apr 2021 22:17:56
 +0200")
Message-ID: <874kfxtl27.fsf@gnu.org>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.2 (gnu/linux)
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="=-=-="
X-Spam-Score: -2.3 (--)
X-Debbugs-Envelope-To: 47867
Cc: guix-devel@gnu.org, Christopher Baines <mail@cbaines.net>,
 jcguu95 <jcguu95@gmail.com>, 47867@debbugs.gnu.org
X-BeenThere: debbugs-submit@debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request@debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit@debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request@debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request@debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces@debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces@debbugs.gnu.org>
X-Spam-Score: -3.3 (---)

[Message part 1 (text/plain, inline)]

Hi Florian,

(Cc: Chris who’s also familiar with (guix http-client).)

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:

> It still gets stuck (sometimes with enlightenment, one time with
> udisks, restarting the install fixed it once).  After getting stuck,
> this different error message is shown now; no TLS error (copied by
> manual typing, there may be typos):
>
> gtk-doc-1.28  653KiB                2.4MiB/s 00:00 [####################] 100.0%
> udisks-2.8.4  842KiB                1.6MiB/s 00:00 [####################] 100.0%
>
> substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%Backtrace:
> substitute: In ice-9/boot-9.scm:
> substitute:   1736:10 17 (with-exception-handler _ _ #:unwind? _ # _)
> substitute: In unknown file:
> substitute:           16 (apply-smob/0 #<thunk 7fc2dbf60520>)
> substitute: In ice-9/boot-9.scm:
> substitute:     718:2 15 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
> substitute: In ice-9/eval.scm:
> substitute:     619:8 14 (_ #(#(#<directory (guile-user) 7fc2dbf63c80>)))
> substitute: In guix/ui.scm:
> substitute:   2164:12 13 (run-guix-command _ . _)
> substitute: In ice-9/boot-9.scm:
> substitute:   1736:10 12 (with-exception-handler _ _ #:unwind? _ # _)
> substitute:   1736:10 11 (with-exception-handler _ _ #:unwind? _ # _)
> substitute:   1731:15 10 (with-exception-handler _ _ #:unwind? _ # _)
> substitute: In guix/scripts/substitute.scm:
> substitute:    745:18  9 (_)
> substitute:    346:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
> substitute: In guix/substitutes.scm:
> substitute:    358:27  7 (lookup-narinfos/diverse _ _ #<procedure 7fc2d3b15000 …>
> substitute:    315:31  6 (lookup-narinfos _ _ #:open-connection _ # _)
> substitute:    238:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
> substitute: In ice-9/boot-9.scm:
> substitute:   1669:16  4 (raise-exception _ #:continuable? _)
> substitute:   1669:16  3 (raise-exception _ #:continuable? _)
> substitute:   1764:13  2 (_ #<&compound-exception _ components: assertion-fail…>)
> substitute:   1669:16  1 (raise-exception _ #:continuable? _)
> substitute:   1669:16  0 (raise-exception _ #:continuable? _)
> substitute:
> substitute: In ice-9/boot-9.scm:1669:16 In procedure raise-exception:
> substitute: In procedure %read-line: Wrong type argument in position 1 (expecting open input port): #<closed: string 7fc2d8796070>
> guix system: error: `/gnu/store/k3n98i1fk9awd5ydv4ry4k4rlpp7i13m7-guix-1.2.0-22.c467718/bin/guix substitute' died unexpectedly

I think I got it: commit 205833b72c5517915a47a50dbe28e7024dc74e57 (then
carried over in 45fce38fb0b6c6796906149ade145b8d3594c1c6) introduced a
call to ‘connect’ in non-tail position.  Once that recursive call to
‘connect’ had completed, ‘http-multiple-get’ would go on in ‘loop’
trying to re-process responses, but at that point there aren’t any
responses left to process.

This problem could only happen if a networking exception would occur
while sending HTTP requests for narinfos.  Thus, it was most likely to
occur when interleaving substitutions and queries, as in the snippet you
provided above, because then ‘http-multiple-get’ was more likely to be
passed a stale reused connection.

Florian, could you try again with the attached patch?

If you have the courage, it would be awesome if you could also try the
patch without the ‘error/again’ bits.  It’s possible that they aren’t
needed now.  I double-checked and the GnuTLS Guile bindings already
handle GNUTLS_E_AGAIN and GNUTLS_E_INTERRUPTED, so my guess is that this
was just a side effect of dealing with stale TLS sessions:

  https://gitlab.com/gnutls/gnutls/-/blob/master/guile/src/core.c#L1042

Thanks a lot for your help!

Ludo’.

[Message part 2 (text/x-patch, inline)]

diff --git a/guix/http-client.scm b/guix/http-client.scm
index a2e11a1b73..b9cf0b1a4b 100644
--- a/guix/http-client.scm
+++ b/guix/http-client.scm
@@ -38,7 +38,7 @@
   #:use-module (guix utils)
   #:use-module (guix base64)
   #:autoload   (gcrypt hash) (sha256)
-  #:autoload   (gnutls) (error/invalid-session)
+  #:autoload   (gnutls) (error/invalid-session error/again)
   #:use-module ((guix build utils)
                 #:select (mkdir-p dump-port))
   #:use-module ((guix build download)
@@ -163,7 +163,8 @@ reusing stale cached connections."
       (if (or (and (eq? key 'system-error)
                    (= EPIPE (system-error-errno `(,key ,@args))))
               (and (eq? key 'gnutls-error)
-                   (eq? (first args) error/invalid-session))
+                   (memq (first args)
+                         (list error/again error/invalid-session)))
               (memq key
                     '(bad-response bad-header bad-header-component)))
           #f
@@ -207,15 +208,14 @@ returning."
         ;; Inherit the HTTP proxying property from P.
         (set-http-proxy-port?! buffer (http-proxy-port? p))
 
-        (unless (false-if-networking-error
-                 (begin
-                   (for-each (cut write-request <> buffer) batch)
-                   (put-bytevector p (get))
-                   (force-output p)
-                   #t))
-          ;; If PORT becomes unusable, open a fresh connection and retry.
-          (close-port p)                          ; close the broken port
-          (connect #f requests result)))
+        ;; Swallow networking errors that could occur due to connection reuse
+        ;; and the like; they will be handled down the road when trying to
+        ;; read responses.
+        (false-if-networking-error
+         (begin
+           (for-each (cut write-request <> buffer) batch)
+           (put-bytevector p (get))
+           (force-output p))))
 
       ;; Now start processing responses.
       (let loop ((sent      batch)
diff --git a/guix/scripts/substitute.scm b/guix/scripts/substitute.scm
index 48309f9b3a..65940591a9 100755
--- a/guix/scripts/substitute.scm
+++ b/guix/scripts/substitute.scm
@@ -45,7 +45,7 @@
                 #:select (uri-abbreviation nar-uri-abbreviation
                           (open-connection-for-uri
                            . guix:open-connection-for-uri)))
-  #:autoload   (gnutls) (error/invalid-session)
+  #:autoload   (gnutls) (error/invalid-session error/again)
   #:use-module (guix progress)
   #:use-module ((guix build syscalls)
                 #:select (set-thread-name))
@@ -417,7 +417,8 @@ server certificates."
         (if (or (and (eq? key 'system-error)
                      (= EPIPE (system-error-errno `(,key ,@args))))
                 (and (eq? key 'gnutls-error)
-                     (eq? (first args) error/invalid-session))
+                     (memq (first args)
+                           (list error/again error/invalid-session)))
                 (memq key '(bad-response bad-header bad-header-component)))
             (proc (open-connection-for-uri/cached uri
                                                   #:verify-certificate? #f

Send a report that this bug log contains spam.