bug#32050: invoke (guix build utils) error reporting lacking

bug#32050: invoke (guix build utils) error reporting lacking

[Maxim Cournoyer]

The error reported by `invoke' isn't accurate, and mutes important
output from the program invoked.

Example of a failed tar extraction:
--8<---------------cut here---------------start------------->8---
/gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("xf" "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2" "--strip-components=1" "-C" "/gnu/store/rw7yzjk1wffza65z6l6rnn25qg97jvh1-docbook-dsssl-doc-1.79" "docbook-dssl-1.79/doc") exit-status: 127 term-signal: #f stop-signal: #f] 68fc80>)'.
--8<---------------cut here---------------end--------------->8---

While reproducing the same error in an containerized environment,
calling the command directly yields:

--8<---------------cut here---------------start------------->8---
tar xf yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2 --strip-components=1 -C $PWD docbook-dssl-1.79/doc
tar: docbook-dssl-1.79/doc: Not found in archive
tar: Exiting with failure status due to previous errors
maxim@apteryx /tmp/docbook-dsssl-doc [env]# echo $?
2
--8<---------------cut here---------------end--------------->8---

Two observations:

1. invoke's reported exit status was wrong (127 rather than 2)
2. The useful error message "docbook-dssl-1.79/doc: Not found in
archive" was masked.

bug#32050: invoke (guix build utils) error reporting lacking

[Maxim Cournoyer]

More problematic even, it seems "invoke" can't do everything that
"system*" can?

For example, the following package builds fine:

--8<---------------cut here---------------start------------->8---
(define-public docbook-dsssl-doc
  (package
    (name "docbook-dsssl-doc")
    (version "1.79")
    (source (origin
              (method url-fetch)
              (uri (string-append "mirror://sourceforge/docbook/"
                                  name "/" version "/"
                                  name "-" version ".tar.bz2"))
              (sha256
               (base32
                "1plp5ngc96pbna4rwglp9glcadnirbm3hlcjb4gjvq1f8biic9lz"))))
    (build-system trivial-build-system)
    (arguments
     `(#:modules ((guix build utils))
       #:builder
       (begin
         (use-modules (guix build utils))
         (let ((source (assoc-ref %build-inputs "source"))
               (out (assoc-ref %outputs "out")))
           (mkdir-p out)
           ;; Extract the "doc" subdirectory.
           (system* "tar" "xf" source "--strip-components=1"
                   "--no-same-owner" "-C" out
                   (string-append "docbook-dsssl-" ,version "/doc"))))))
    (native-inputs
     `(("bzip2", bzip2)
       ("tar" ,tar)))
    (home-page "https://docbook.org/")
    (synopsis "DocBook DSSSL style sheets documentation")
    (description "Documentation for the DocBook DSSSL style sheets.")
    (license non-copyleft)))
--8<---------------cut here---------------end--------------->8---

,run-in-store (build-package docbook-dsssl-doc #:use-substitutes? #t #:dry-run? #f)
/gnu/store/ljr8xn3qbr3lahr29zc0lbki9x33zls6-docbook-dsssl-doc-1.79
$4 = #t

But changing just "system*" to "invoke", I get:

--8<---------------cut here---------------start------------->8---
@ build-remote /gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv 192.168.1.105
Backtrace:
           2 (primitive-load "/gnu/store/06zszks9mwp52gih8j0mj5bahfi?")
In ice-9/eval.scm:
   191:35  1 (_ #f)
In /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:
    616:6  0 (invoke _ . _)

/gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("xf" "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2" "--strip-components=1" "--no-same-owner" "-C" "/gnu/store/83yjsgvvapffhklg8md5cqa6gmb2dmqg-docbook-dsssl-doc-1.79" "docbook-dsssl-1.79/doc") exit-status: 127 term-signal: #f stop-signal: #f] 68fcc0>)'.
builder for `/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' failed with exit code 1
derivation '/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' offloaded to '192.168.1.105' failed: build of `/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' failed
While executing meta-command:
Throw to key `srfi-34' with args `(#<condition &nix-protocol-error [message: "build of `/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' failed" status: 100] a7228a0>)'.
--8<---------------cut here---------------end--------------->8---

Thanks,

Maxim

bug#32050: invoke (guix build utils) error reporting lacking

[Mark H Weaver]

Hi Maxim,

Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:

> More problematic even, it seems "invoke" can't do everything that
> "system*" can?
>
> For example, the following package builds fine:
>
> (define-public docbook-dsssl-doc
>   (package
>     (name "docbook-dsssl-doc")
>     (version "1.79")
>     (source (origin
>               (method url-fetch)
>               (uri (string-append "mirror://sourceforge/docbook/"
>                                   name "/" version "/"
>                                   name "-" version ".tar.bz2"))
>               (sha256
>                (base32
>                 "1plp5ngc96pbna4rwglp9glcadnirbm3hlcjb4gjvq1f8biic9lz"))))
>     (build-system trivial-build-system)
>     (arguments
>      `(#:modules ((guix build utils))
>        #:builder
>        (begin
>          (use-modules (guix build utils))
>          (let ((source (assoc-ref %build-inputs "source"))
>                (out (assoc-ref %outputs "out")))
>            (mkdir-p out)
>            ;; Extract the "doc" subdirectory.
>            (system* "tar" "xf" source "--strip-components=1"
>                    "--no-same-owner" "-C" out
>                    (string-append "docbook-dsssl-" ,version "/doc"))))))
>     (native-inputs
>      `(("bzip2", bzip2)
>        ("tar" ,tar)))
>     (home-page "https://docbook.org/")
>     (synopsis "DocBook DSSSL style sheets documentation")
>     (description "Documentation for the DocBook DSSSL style sheets.")
>     (license non-copyleft)))
>
>
> ,run-in-store (build-package docbook-dsssl-doc #:use-substitutes? #t #:dry-run? #f)
> /gnu/store/ljr8xn3qbr3lahr29zc0lbki9x33zls6-docbook-dsssl-doc-1.79
> $4 = #t

Did you check to see if the extraction actually succeeded?

In this case, I don't see how it could have.  When using 'tar' from
within 'trivial-build-system', you need to add 'bzip2' to PATH, or else
'tar' will fail because it can't find 'bzip2'.  There are many examples
of setting PATH in (gnu packages fonts).

Because of the way you are using 'system*' here without the usual
'zero?' wrapped around it, the numeric result code is returned as the
result of the builder, and all numbers (even 0) are considered true in
Scheme.  So, this build will always succeed, ignoring errors from 'tar'.

> But changing just "system*" to "invoke", I get:
>
> @ build-remote /gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv 192.168.1.105
> Backtrace:
>            2 (primitive-load "/gnu/store/06zszks9mwp52gih8j0mj5bahfi?")
> In ice-9/eval.scm:
>    191:35  1 (_ #f)
> In /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:
>     616:6  0 (invoke _ . _)
>
> /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
> Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("xf" "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2" "--strip-components=1" "--no-same-owner" "-C" "/gnu/store/83yjsgvvapffhklg8md5cqa6gmb2dmqg-docbook-dsssl-doc-1.79" "docbook-dsssl-1.79/doc") exit-status: 127 term-signal: #f stop-signal: #f] 68fcc0>)'.
> builder for `/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' failed with exit code 1
> derivation '/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' offloaded to '192.168.1.105' failed: build of `/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' failed
> While executing meta-command:
> Throw to key `srfi-34' with args `(#<condition &nix-protocol-error [message: "build of `/gnu/store/fdcg5nazw2jvpb7k4mq7q0750gq22zh7-docbook-dsssl-doc-1.79.drv' failed" status: 100] a7228a0>)'.

Changing 'system*' to 'invoke' allowed you to see that something went
wrong.

> The error reported by `invoke' isn't accurate, and mutes important
> output from the program invoked.
>
> Example of a failed tar extraction:
>
> /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
> Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("xf" "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2" "--strip-components=1" "-C" "/gnu/store/rw7yzjk1wffza65z6l6rnn25qg97jvh1-docbook-dsssl-doc-1.79" "docbook-dssl-1.79/doc") exit-status: 127 term-signal: #f stop-signal: #f] 68fc80>)'.
>
>
> While reproducing the same error in an containerized environment,
> calling the command directly yields:
>
> tar xf yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2 --strip-components=1 -C $PWD docbook-dssl-1.79/doc
> tar: docbook-dssl-1.79/doc: Not found in archive
> tar: Exiting with failure status due to previous errors
> maxim@apteryx /tmp/docbook-dsssl-doc [env]# echo $?
> 2
>
> Two observations:
>
> 1. invoke's reported exit status was wrong (127 rather than 2)
> 2. The useful error message "docbook-dssl-1.79/doc: Not found in
> archive" was masked.

I think what happened is that 'tar' actually failed in two different
ways.  In the first case, where the result code was 127, it failed
because 'bzip2' was not found in PATH.  In the second case, it failed
because "docbook-dssl-1.79/doc" was not found in the archive.

Or at least that's my guess.

     Regards,
       Mark

bug#32050: invoke (guix build utils) error reporting lacking

[Maxim Cournoyer]

Hi Mark,

Mark H Weaver <mhw@netris.org> writes:

[...]

> Did you check to see if the extraction actually succeeded?
>
> In this case, I don't see how it could have.  When using 'tar' from
> within 'trivial-build-system', you need to add 'bzip2' to PATH, or else
> 'tar' will fail because it can't find 'bzip2'.  There are many examples
> of setting PATH in (gnu packages fonts).

OK. I now understand that the trivial-build-system does exactly nothing
for us, so it doesn't even sets the "PATH" environment variable. This
wasn't obvious to me, thank for pointing it out!

> Changing 'system*' to 'invoke' allowed you to see that something went
> wrong.

Right, my confusion stemmed from the unset PATH variable; tar itself
would return exit code 127 (command not found) in the
trivial-build-system, but I couldn't reproduce directly in a
containerized guix environment because there is a profile generation
hook there which does set the PATH.

>> The error reported by `invoke' isn't accurate, and mutes important
>> output from the program invoked.
>>
>> Example of a failed tar extraction:
>>
>> /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
>> Throw to key `srfi-34' with args `(#<condition &invoke-error
>> [program: "tar" arguments: ("xf"
>> "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2"
>> "--strip-components=1" "-C"
>> "/gnu/store/rw7yzjk1wffza65z6l6rnn25qg97jvh1-docbook-dsssl-doc-1.79"
>> "docbook-dssl-1.79/doc") exit-status: 127 term-signal: #f
>> stop-signal: #f] 68fc80>)'.

It seems that the "system" and "system*" commands of Guile as well as
our "invoke" do preserve the stdout/stderr, as when testing it manually
I can see the useful "sh: tar: command not found" message:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,use (guix build utils)
scheme@(guile-user)> (system "tar xf yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2")
sh: tar: command not found
$1 = 32512
scheme@(guile-user)> (invoke "tar" "xf" "yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2")
In execvp of tar: No such file or directory
guix/build/utils.scm:616:6: In procedure invoke:
Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("xf" "yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2") exit-status: 127 term-signal: #f stop-signal: #f] 1e3dc40>)'.

Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
--8<---------------cut here---------------end--------------->8---

Unfortunately, when called from the builder side of Guix, this
information seems to be lost:

--8<---------------cut here---------------start------------->8---
./pre-inst-env guix build --no-build-hook --check docbook-dsssl-doc
@ build-started /gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv - x86_64-linux /var/log/guix/drvs/4r//a70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv.bz2
Backtrace:
           2 (primitive-load "/gnu/store/kj0nr8i617gjwypalfs065jllhm?")
In ice-9/eval.scm:
   191:35  1 (_ #f)
In /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:
    616:6  0 (invoke _ . _)

/gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("-xf" "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2" "--strip-components=1" "--no-same-owner" "-C" "/gnu/store/ppf9bhzyqphmc9cvwhq8pc3yfir2qd3m-docbook-dsssl-doc-1.79" "docbook-dsssl-1.79/doc") exit-status: 127 term-signal: #f stop-signal: #f] 68fcc0>)'.
builder for `/gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv' failed with exit code 1
@ build-failed /gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv - 1 builder for `/gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv' failed with exit code 1
guix build: error: build failed: build of
`/gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv'
failed
--8<---------------cut here---------------end--------------->8---

Could it be preserved? It'd be very useful when debugging :)

Maxim

bug#32050: invoke (guix build utils) error reporting lacking

[Maxim Cournoyer]

Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:

[...]

> It seems that the "system" and "system*" commands of Guile as well as
> our "invoke" do preserve the stdout/stderr, as when testing it manually
> I can see the useful "sh: tar: command not found" message:
>
> scheme@(guile-user)> ,use (guix build utils)
> scheme@(guile-user)> (system "tar xf yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2")
> sh: tar: command not found
> $1 = 32512
> scheme@(guile-user)> (invoke "tar" "xf" "yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2")
> In execvp of tar: No such file or directory
> guix/build/utils.scm:616:6: In procedure invoke:
> Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("xf" "yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2") exit-status: 127 term-signal: #f stop-signal: #f] 1e3dc40>)'.
>
> Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
>
>
> Unfortunately, when called from the builder side of Guix, this
> information seems to be lost:
>
> ./pre-inst-env guix build --no-build-hook --check docbook-dsssl-doc
> @ build-started /gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv - x86_64-linux /var/log/guix/drvs/4r//a70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv.bz2
> Backtrace:
>            2 (primitive-load "/gnu/store/kj0nr8i617gjwypalfs065jllhm?")
> In ice-9/eval.scm:
>    191:35  1 (_ #f)
> In /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:
>     616:6  0 (invoke _ . _)
>
> /gnu/store/xlj36j9dw581iah51iyjgi75iikrj55h-module-import/guix/build/utils.scm:616:6: In procedure invoke:
> Throw to key `srfi-34' with args `(#<condition &invoke-error [program: "tar" arguments: ("-xf" "/gnu/store/yanfzfi7rdyf5scf5h65xbkn7xg0nnbn-docbook-dsssl-doc-1.79.tar.bz2" "--strip-components=1" "--no-same-owner" "-C" "/gnu/store/ppf9bhzyqphmc9cvwhq8pc3yfir2qd3m-docbook-dsssl-doc-1.79" "docbook-dsssl-1.79/doc") exit-status: 127 term-signal: #f stop-signal: #f] 68fcc0>)'.
> builder for `/gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv' failed with exit code 1
> @ build-failed /gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv - 1 builder for `/gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv' failed with exit code 1
> guix build: error: build failed: build of
> `/gnu/store/4ra70nwni8mcjyd2wfx7fqvsl4fpfs5m-docbook-dsssl-doc-1.79.drv'
> failed
>
> Could it be preserved? It'd be very useful when debugging :)

I've investigated a bit, and as far as I can see by reading guix
sources, the build log output would be displayed and any error reported
by the `process-stderr' procedure in (guix store). This procedure
behavior seems to depend closely on that of the guix daemon (server), so
the problem could lie on the daemon side as well, so that's where I'll
try digging next.

Maxim

bug#32050: invoke (guix build utils) error reporting lacking

[Maxim Cournoyer]

Hello,

I think my original observations must have occured in Emacs while using
Geiser.  It has to do with what (current-output-port) is bound to in the
REPL (see: https://github.com/jaor/geiser/issues/83).

I'm closing, as I haven't seen this issue in almost 2 years when using
Guix from the command line.

Maxim