got unexpected path `Backtrace:' from substituter

DoneSubmitted by Zhu Zihao.
Details
2 participants
  • Zhu Zihao
  • Ludovic Courtès
Owner
unassigned
Severity
important
Z
Z
Zhu Zihao wrote on 7 Feb 2021 13:42
(address . bug-guix@gnu.org)
86a6sgcan1.fsf@163.com
This issue is similar with https://issues.guix.gnu.org/45828.But it
still not fixed in 127a88d390417d5d7b1b4a18c1b69c7169dcaf34.

When you have multiple substituters, Guix will try to fetch narinfo from
the second or even third substituters, and it dies.

```
chino@asus-laptop:~$ guix build opencv --substitute-urls="https://mirror.sjtu.edu.cn/guixhttps://mirror.guix.org.cn https://mirror.c1r3u.xyz https://ci.guix.gnu.org"
substitute: updating substitutes from 'https://mirror.sjtu.edu.cn/guix'...100.0%
substitute:
guix build: error: got unexpected path `Backtrace:' from substituter
```

If there's one substituter, it will work and do the substitution.
--
Retrieve my PGP public key:

gpg --recv-keys D47A9C8B2AE3905B563D9135BE42B352A9F6821F

Zihao
-----BEGIN PGP SIGNATURE-----

iIsEARYIADMWIQTUepyLKuOQW1Y9kTW+QrNSqfaCHwUCYB/gIxUcYWxsX2J1dF9s
YXN0QDE2My5jb20ACgkQvkKzUqn2gh8rEQEAq+HkamvgiP8oj9q6gfbtrO3WdlWV
s5Y1bRBz1b8OMNwBAL3pDtTdm3PaC4KCSUEO94a2t0Mj4mR/0kB2FM3E1bwC
=EtzF
-----END PGP SIGNATURE-----

L
L
Ludovic Courtès wrote on 19 Feb 2021 16:17
control message for bug #46362
(address . control@debbugs.gnu.org)
8735xsm6iq.fsf@gnu.org
severity 46362 important
quit
L
L
Ludovic Courtès wrote on 25 Feb 2021 09:21
Re: bug#46362: got unexpected path `Backtrace:' from substituter
(name . Zhu Zihao)(address . all_but_last@163.com)(address . 46362@debbugs.gnu.org)
87eeh41rsb.fsf@gnu.org
Hi,

Zhu Zihao <all_but_last@163.com> skribis:

Toggle quote (13 lines)
> This issue is similar with https://issues.guix.gnu.org/45828.But it
> still not fixed in 127a88d390417d5d7b1b4a18c1b69c7169dcaf34.
>
> When you have multiple substituters, Guix will try to fetch narinfo from
> the second or even third substituters, and it dies.
>
> ```
> chino@asus-laptop:~$ guix build opencv --substitute-urls="https://mirror.sjtu.edu.cn/guix https://mirror.guix.org.cn https://mirror.c1r3u.xyz https://ci.guix.gnu.org"
> substitute: updating substitutes from 'https://mirror.sjtu.edu.cn/guix'... 100.0%
> substitute:
> guix build: error: got unexpected path `Backtrace:' from substituter
> ```

Commit ee3226e9d54891c7e696912245e4904435be191c addresses the
error-reporting issue: now the backtrace will be properly displayed (we
still need to update the ‘guix’ package before you can deploy the fix.)

Toggle quote (2 lines)
> If there's one substituter, it will work and do the substitution.

Did you find out which of these substitute URLs is causing troubles? I
tried the exact same command and it works for me.

Thanks,
Ludo’.
L
L
Ludovic Courtès wrote on 24 Mar 2021 15:39
control message for bug #46362
(address . control@debbugs.gnu.org)
87blb8fweg.fsf@gnu.org
tags 46362 fixed
close 46362
quit
L
L
Ludovic Courtès wrote on 6 Apr 2021 11:25
(address . control@debbugs.gnu.org)
87pmz7ojc4.fsf@gnu.org
reopen 46362
tags 46362 - fixed patch
quit
L
L
Ludovic Courtès wrote on 6 Apr 2021 12:20
Re: bug#46362: got unexpected path `Backtrace:' from substituter
(address . 46362@debbugs.gnu.org)
87h7kjogt9.fsf@gnu.org
Hi,

Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (10 lines)
>> chino@asus-laptop:~$ guix build opencv --substitute-urls="https://mirror.sjtu.edu.cn/guixhttps://mirror.guix.org.cn https://mirror.c1r3u.xyz https://ci.guix.gnu.org"
>> substitute: updating substitutes from 'https://mirror.sjtu.edu.cn/guix'... 100.0%
>> substitute:
>> guix build: error: got unexpected path `Backtrace:' from substituter
>> ```
>
> Commit ee3226e9d54891c7e696912245e4904435be191c addresses the
> error-reporting issue: now the backtrace will be properly displayed (we
> still need to update the ‘guix’ package before you can deploy the fix.)

This commit did the job, but there would still be cases where error
messages would end up on file descriptor 2 (not surprisingly) and which
the daemon would wrongfully interpret as a status message from ‘guix
substitute’, leading to obscure crashes. Sébastien gives an example

guix install: error: got unexpected path `/gnu/store/pwcp239kjf7lnj5i4lkdzcfcxwcfyk72-bash-minimal-5.0.16/bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.utf8)' from substituter

The attached patch swaps use of file descriptors 2 and 4 of ‘guix
substitute’: FD 2 is now used for regular error reporting, while FD 4 is
used to communicate responses to the daemon. This is more natural and
avoids the kind of problem discussed above.

I’ll push this change if there are no objections.

Thanks,
Ludo’.
From d85353dd4bfaa57a7d5803dade91d806a169295a Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Ludovic=20Court=C3=A8s?= <ludo@gnu.org>
Date: Tue, 6 Apr 2021 12:10:29 +0200
Subject: [PATCH] daemon: 'guix substitute' replies on FD 4.

This avoids the situation where error messages would unintentionally go
to stderr and be wrongfully interpreted as a reply by the daemon.

This is a followup to ee3226e9d54891c7e696912245e4904435be191c.

* guix/scripts/substitute.scm (display-narinfo-data): Add 'port'
parameter and honor it.
(process-query): Likewise.
(process-substitution): Likewise.
(%error-to-file-descriptor-4?, with-redirected-error-port): Remove.
(%reply-file-descriptor): New variable.
(guix-substitute): Remove use of 'with-redirected-error-port'. Define
'reply-port' and pass it to 'process-query' and 'process-substitution'.
* nix/libstore/build.cc (SubstitutionGoal::handleChildOutput): Swap
'builderOut' and 'fromAgent'.
* nix/libstore/local-store.cc (LocalStore::getLineFromSubstituter):
Likewise.
* tests/substitute.scm <top level>: Set '%reply-file-descriptor'
rather than '%error-to-file-descriptor-4?'.
---
guix/scripts/substitute.scm | 183 +++++++++++++++++-------------------
nix/libstore/build.cc | 4 +-
nix/libstore/local-store.cc | 12 +--
tests/substitute.scm | 4 +-
4 files changed, 95 insertions(+), 108 deletions(-)

Toggle diff (351 lines)
diff --git a/guix/scripts/substitute.scm b/guix/scripts/substitute.scm
index 79eaabd8fd..48309f9b3a 100755
--- a/guix/scripts/substitute.scm
+++ b/guix/scripts/substitute.scm
@@ -63,7 +63,7 @@
   #:use-module (web uri)
   #:use-module (guix http-client)
   #:export (%allow-unauthenticated-substitutes?
-            %error-to-file-descriptor-4?
+            %reply-file-descriptor
 
             substitute-urls
             guix-substitute))
@@ -279,29 +279,29 @@ Internal tool to substitute a pre-built binary to a local build.\n"))
   "Evaluate EXP...  Return its CPU usage as a fraction between 0 and 1."
   (call-with-cpu-usage-monitoring (lambda () exp ...)))
 
-(define (display-narinfo-data narinfo)
-  "Write to the current output port the contents of NARINFO in the format
-expected by the daemon."
-  (format #t "~a\n~a\n~a\n"
+(define (display-narinfo-data port narinfo)
+  "Write to PORT the contents of NARINFO in the format expected by the
+daemon."
+  (format port "~a\n~a\n~a\n"
           (narinfo-path narinfo)
           (or (and=> (narinfo-deriver narinfo)
                      (cute string-append (%store-prefix) "/" <>))
               "")
           (length (narinfo-references narinfo)))
-  (for-each (cute format #t "~a/~a~%" (%store-prefix) <>)
+  (for-each (cute format port "~a/~a~%" (%store-prefix) <>)
             (narinfo-references narinfo))
 
   (let-values (((uri compression file-size)
                 (narinfo-best-uri narinfo
                                   #:fast-decompression?
                                   %prefer-fast-decompression?)))
-    (format #t "~a\n~a\n"
+    (format port "~a\n~a\n"
             (or file-size 0)
             (or (narinfo-size narinfo) 0))))
 
-(define* (process-query command
+(define* (process-query port command
                         #:key cache-urls acl)
-  "Reply to COMMAND, a query as written by the daemon to this process's
+  "Reply on PORT to COMMAND, a query as written by the daemon to this process's
 standard input.  Use ACL as the access-control list against which to check
 authorized substitutes."
   (define valid?
@@ -338,17 +338,17 @@ authorized substitutes."
                            #:open-connection open-connection-for-uri/cached
                            #:make-progress-reporter make-progress-reporter)))
        (for-each (lambda (narinfo)
-                   (format #t "~a~%" (narinfo-path narinfo)))
+                   (format port "~a~%" (narinfo-path narinfo)))
                  substitutable)
-       (newline)))
+       (newline port)))
     (("info" paths ..1)
      ;; Reply info about PATHS if it's in CACHE-URLS.
      (let ((substitutable (lookup-narinfos/diverse
                            cache-urls paths valid?
                            #:open-connection open-connection-for-uri/cached
                            #:make-progress-reporter make-progress-reporter)))
-       (for-each display-narinfo-data substitutable)
-       (newline)))
+       (for-each (cut display-narinfo-data port <>) substitutable)
+       (newline port)))
     (wtf
      (error "unknown `--query' command" wtf))))
 
@@ -428,14 +428,14 @@ server certificates."
   "Bind PORT with EXP... to a socket connected to URI."
   (call-with-cached-connection uri (lambda (port) exp ...)))
 
-(define* (process-substitution store-item destination
+(define* (process-substitution port store-item destination
                                #:key cache-urls acl
                                deduplicate? print-build-trace?)
   "Substitute STORE-ITEM (a store file name) from CACHE-URLS, and write it to
 DESTINATION as a nar file.  Verify the substitute against ACL, and verify its
 hash against what appears in the narinfo.  When DEDUPLICATE? is true, and if
-DESTINATION is in the store, deduplicate its files.  Print a status line on
-the current output port."
+DESTINATION is in the store, deduplicate its files.  Print a status line to
+PORT."
   (define narinfo
     (lookup-narinfo cache-urls store-item
                     (if (%allow-unauthenticated-substitutes?)
@@ -565,10 +565,10 @@ the current output port."
       (let ((actual (get-hash)))
         (if (bytevector=? actual expected)
             ;; Tell the daemon that we're done.
-            (format (current-output-port) "success ~a ~a~%"
+            (format port "success ~a ~a~%"
                     (narinfo-hash narinfo) (narinfo-size narinfo))
             ;; The actual data has a different hash than that in NARINFO.
-            (format (current-output-port) "hash-mismatch ~a ~a ~a~%"
+            (format port "hash-mismatch ~a ~a ~a~%"
                     (hash-algorithm-name algorithm)
                     (bytevector->nix-base32-string expected)
                     (bytevector->nix-base32-string actual)))))))
@@ -682,28 +682,10 @@ default value."
   (unless (string->uri uri)
     (leave (G_ "~a: invalid URI~%") uri)))
 
-(define %error-to-file-descriptor-4?
-  ;; Whether to direct 'current-error-port' to file descriptor 4 like
-  ;; 'guix-daemon' expects.
-  (make-parameter #t))
-
-;; The daemon's agent code opens file descriptor 4 for us and this is where
-;; stderr should go.
-(define-syntax-rule (with-redirected-error-port exp ...)
-  "Evaluate EXP... with the current error port redirected to file descriptor 4
-if needed, as expected by the daemon's agent."
-  (let ((thunk (lambda () exp ...)))
-    (if (%error-to-file-descriptor-4?)
-        (parameterize ((current-error-port (fdopen 4 "wl")))
-          ;; Redirect diagnostics to file descriptor 4 as well.
-          (guix-warning-port (current-error-port))
-
-          ;; 'with-continuation-barrier' captures the initial value of
-          ;; 'current-error-port' to report backtraces in case of uncaught
-          ;; exceptions.  Without it, backtraces would be printed to FD 2,
-          ;; thereby confusing the daemon.
-          (with-continuation-barrier thunk))
-        (thunk))))
+(define %reply-file-descriptor
+  ;; The file descriptor where replies to the daemon must be sent, or #f to
+  ;; use the current output port instead.
+  (make-parameter 4))
 
 (define-command (guix-substitute . args)
   (category internal)
@@ -719,68 +701,73 @@ if needed, as expected by the daemon's agent."
   (define deduplicate?
     (find-daemon-option "deduplicate"))
 
-  (with-redirected-error-port
-    (mkdir-p %narinfo-cache-directory)
-    (maybe-remove-expired-cache-entries %narinfo-cache-directory
-                                        cached-narinfo-files
-                                        #:entry-expiration
-                                        cached-narinfo-expiration-time
-                                        #:cleanup-period
-                                        %narinfo-expired-cache-entry-removal-delay)
-    (check-acl-initialized)
+  (define reply-port
+    ;; Port used to reply to the daemon.
+    (if (%reply-file-descriptor)
+        (fdopen (%reply-file-descriptor) "wl")
+        (current-output-port)))
 
-    ;; Sanity-check SUBSTITUTE-URLS so we can provide a meaningful error
-    ;; message.
-    (for-each validate-uri (substitute-urls))
+  (mkdir-p %narinfo-cache-directory)
+  (maybe-remove-expired-cache-entries %narinfo-cache-directory
+                                      cached-narinfo-files
+                                      #:entry-expiration
+                                      cached-narinfo-expiration-time
+                                      #:cleanup-period
+                                      %narinfo-expired-cache-entry-removal-delay)
+  (check-acl-initialized)
 
-    ;; Attempt to install the client's locale so that messages are suitably
-    ;; translated.  LC_CTYPE must be a UTF-8 locale; it's the case by default
-    ;; so don't change it.
-    (match (or (find-daemon-option "untrusted-locale")
-               (find-daemon-option "locale"))
-      (#f     #f)
-      (locale (false-if-exception (setlocale LC_MESSAGES locale))))
+  ;; Sanity-check SUBSTITUTE-URLS so we can provide a meaningful error
+  ;; message.
+  (for-each validate-uri (substitute-urls))
 
-    (catch 'system-error
-      (lambda ()
-        (set-thread-name "guix substitute"))
-      (const #t))                                 ;GNU/Hurd lacks 'prctl'
+  ;; Attempt to install the client's locale so that messages are suitably
+  ;; translated.  LC_CTYPE must be a UTF-8 locale; it's the case by default
+  ;; so don't change it.
+  (match (or (find-daemon-option "untrusted-locale")
+             (find-daemon-option "locale"))
+    (#f     #f)
+    (locale (false-if-exception (setlocale LC_MESSAGES locale))))
 
-    (with-networking
-     (with-error-handling                         ; for signature errors
-       (match args
-         (("--query")
-          (let ((acl (current-acl)))
-            (let loop ((command (read-line)))
-              (or (eof-object? command)
-                  (begin
-                    (process-query command
-                                   #:cache-urls (substitute-urls)
-                                   #:acl acl)
-                    (loop (read-line)))))))
-         (("--substitute")
-          ;; Download STORE-PATH and store it as a Nar in file DESTINATION.
-          ;; Specify the number of columns of the terminal so the progress
-          ;; report displays nicely.
-          (parameterize ((current-terminal-columns (client-terminal-columns)))
-            (let loop ()
-              (match (read-line)
-                ((? eof-object?)
-                 #t)
-                ((= string-tokenize ("substitute" store-path destination))
-                 (process-substitution store-path destination
-                                       #:cache-urls (substitute-urls)
-                                       #:acl (current-acl)
-                                       #:deduplicate? deduplicate?
-                                       #:print-build-trace?
-                                       print-build-trace?)
-                 (loop))))))
-         ((or ("-V") ("--version"))
-          (show-version-and-exit "guix substitute"))
-         (("--help")
-          (show-help))
-         (opts
-          (leave (G_ "~a: unrecognized options~%") opts)))))))
+  (catch 'system-error
+    (lambda ()
+      (set-thread-name "guix substitute"))
+    (const #t))                                   ;GNU/Hurd lacks 'prctl'
+
+  (with-networking
+   (with-error-handling                           ; for signature errors
+     (match args
+       (("--query")
+        (let ((acl (current-acl)))
+          (let loop ((command (read-line)))
+            (or (eof-object? command)
+                (begin
+                  (process-query reply-port command
+                                 #:cache-urls (substitute-urls)
+                                 #:acl acl)
+                  (loop (read-line)))))))
+       (("--substitute")
+        ;; Download STORE-PATH and store it as a Nar in file DESTINATION.
+        ;; Specify the number of columns of the terminal so the progress
+        ;; report displays nicely.
+        (parameterize ((current-terminal-columns (client-terminal-columns)))
+          (let loop ()
+            (match (read-line)
+              ((? eof-object?)
+               #t)
+              ((= string-tokenize ("substitute" store-path destination))
+               (process-substitution reply-port store-path destination
+                                     #:cache-urls (substitute-urls)
+                                     #:acl (current-acl)
+                                     #:deduplicate? deduplicate?
+                                     #:print-build-trace?
+                                     print-build-trace?)
+               (loop))))))
+       ((or ("-V") ("--version"))
+        (show-version-and-exit "guix substitute"))
+       (("--help")
+        (show-help))
+       (opts
+        (leave (G_ "~a: unrecognized options~%") opts))))))
 
 ;;; Local Variables:
 ;;; eval: (put 'with-timeout 'scheme-indent-function 1)
diff --git a/nix/libstore/build.cc b/nix/libstore/build.cc
index 4f486f0822..5697ae5a43 100644
--- a/nix/libstore/build.cc
+++ b/nix/libstore/build.cc
@@ -3158,13 +3158,13 @@ void SubstitutionGoal::finished()
 void SubstitutionGoal::handleChildOutput(int fd, const string & data)
 {
     if (verbosity >= settings.buildVerbosity
-	&& fd == substituter->builderOut.readSide) {
+	&& fd == substituter->fromAgent.readSide) {
 	writeToStderr(data);
 	/* Don't write substitution output to a log file for now.  We
 	   probably should, though. */
     }
 
-    if (fd == substituter->fromAgent.readSide) {
+    if (fd == substituter->builderOut.readSide) {
 	/* DATA may consist of several lines.  Process them one by one.  */
 	string input = data;
 	while (!input.empty()) {
diff --git a/nix/libstore/local-store.cc b/nix/libstore/local-store.cc
index c304e2ddd1..675d1ba66f 100644
--- a/nix/libstore/local-store.cc
+++ b/nix/libstore/local-store.cc
@@ -780,8 +780,8 @@ Path LocalStore::queryPathFromHashPart(const string & hashPart)
     });
 }
 
-/* Read a line from the substituter's stdout, while also processing
-   its stderr. */
+/* Read a line from the substituter's reply file descriptor, while also
+   processing its stderr. */
 string LocalStore::getLineFromSubstituter(Agent & run)
 {
     string res, err;
@@ -802,9 +802,9 @@ string LocalStore::getLineFromSubstituter(Agent & run)
         }
 
         /* Completely drain stderr before dealing with stdout. */
-        if (FD_ISSET(run.builderOut.readSide, &fds)) {
+        if (FD_ISSET(run.fromAgent.readSide, &fds)) {
             char buf[4096];
-            ssize_t n = read(run.builderOut.readSide, (unsigned char *) buf, sizeof(buf));
+            ssize_t n = read(run.fromAgent.readSide, (unsigned char *) buf, sizeof(buf));
             if (n == -1) {
                 if (errno == EINTR) continue;
                 throw SysError("reading from substituter's stderr");
@@ -822,9 +822,9 @@ string LocalStore::getLineFromSubstituter(Agent & run)
         }
 
         /* Read from stdout until we get a newline or the buffer is empty. */
-        else if (FD_ISSET(run.fromAgent.readSide, &fds)) {
+        else if (FD_ISSET(run.builderOut.readSide, &fds)) {
 	    unsigned char c;
-	    readFull(run.fromAgent.readSide, (unsigned char *) &c, 1);
+	    readFull(run.builderOut.readSide, (unsigned char *) &c, 1);
 	    if (c == '\n') {
 		if (!err.empty()) printMsg(lvlError, "substitute: " + err);
 		return res;
diff --git a/tests/substitute.scm b/tests/substitute.scm
index 697abc4684..21b513e1d8 100644
--- a/tests/substitute.scm
+++ b/tests/substitute.scm
@@ -1,6 +1,6 @@
 ;;; GNU Guix --- Functional package management for GNU
 ;;; Copyright © 2014 Nikita Karetnikov <nikita@karetnikov.org>
-;;; Copyright © 2014, 2015, 2017, 2018, 2019 Ludovic Courtès <ludo@gnu.org>
+;;; Copyright © 2014, 2015, 2017, 2018, 2019, 2021 Ludovic Courtès <ludo@gnu.org>
 ;;;
 ;;; This file is part of GNU Guix.
 ;;;
@@ -198,7 +198,7 @@ a file for NARINFO."
 
 ;; Never use file descriptor 4, unlike what happens when invoked by the
 ;; daemon.
-(%error-to-file-descriptor-4? #f)
+(%reply-file-descriptor #f)
 
 
 (test-equal "query narinfo without signature"
-- 
2.31.1
L
L
Ludovic Courtès wrote on 6 Apr 2021 12:20
control message for bug #47297
(address . control@debbugs.gnu.org)
87ft03ogsh.fsf@gnu.org
block 47297 by 46362
quit
L
L
Ludovic Courtès wrote on 9 Apr 2021 18:10
Re: bug#46362: got unexpected path `Backtrace:' from substituter
(address . 46362-done@debbugs.gnu.org)
87im4v4ewp.fsf@gnu.org
Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (32 lines)
>>From d85353dd4bfaa57a7d5803dade91d806a169295a Mon Sep 17 00:00:00 2001
> From: =?UTF-8?q?Ludovic=20Court=C3=A8s?= <ludo@gnu.org>
> Date: Tue, 6 Apr 2021 12:10:29 +0200
> Subject: [PATCH] daemon: 'guix substitute' replies on FD 4.
>
> This avoids the situation where error messages would unintentionally go
> to stderr and be wrongfully interpreted as a reply by the daemon.
>
> Fixes <https://bugs.gnu.org/46362>.
> This is a followup to ee3226e9d54891c7e696912245e4904435be191c.
>
> * guix/scripts/substitute.scm (display-narinfo-data): Add 'port'
> parameter and honor it.
> (process-query): Likewise.
> (process-substitution): Likewise.
> (%error-to-file-descriptor-4?, with-redirected-error-port): Remove.
> (%reply-file-descriptor): New variable.
> (guix-substitute): Remove use of 'with-redirected-error-port'. Define
> 'reply-port' and pass it to 'process-query' and 'process-substitution'.
> * nix/libstore/build.cc (SubstitutionGoal::handleChildOutput): Swap
> 'builderOut' and 'fromAgent'.
> * nix/libstore/local-store.cc (LocalStore::getLineFromSubstituter):
> Likewise.
> * tests/substitute.scm <top level>: Set '%reply-file-descriptor'
> rather than '%error-to-file-descriptor-4?'.
> ---
> guix/scripts/substitute.scm | 183 +++++++++++++++++-------------------
> nix/libstore/build.cc | 4 +-
> nix/libstore/local-store.cc | 12 +--
> tests/substitute.scm | 4 +-
> 4 files changed, 95 insertions(+), 108 deletions(-)

Pushed as 2d73086262e1fb33cd0f0f16f74a495fe06b38aa with the
corresponding ‘guix’ package update in
ec8d09ee672e0d357bb5bb597464c8b168f14bfb.

Ludo’.
Closed
?
Your comment

This issue is archived.

To comment on this conversation send email to 46362@debbugs.gnu.org